Prefix plugin logs with LocalPlayerId

Add a per-instance local-player log prefix and apply it to networking and main plugin logs to make shared Fallout4Together.log entries readable when multiple instances run. Introduces F4T::Networking::GetLocalPlayerLogPrefix() (declared in F4TNetworking.h, implemented in F4TNetworking.cpp) and updates numerous REX::INFO/WARN calls to include the prefix. Also: only log sent player transforms after SendTransformPacket succeeds, add a small TODO comment about per-instance log files, and update docs (dev-log.md and plugin/setup.md) and the setup checklist to reflect the prefixed logging behavior. The prefix reads the assigned player ID via the thread-safe remote-player accessor and defaults to "[LocalPlayerId=unassigned]" before assignment.
This commit is contained in:
2026-05-31 20:55:32 +12:00
parent 320033f5b8
commit c35659bc30
5 changed files with 120 additions and 34 deletions
+28
View File
@@ -516,6 +516,34 @@ Player position: X=2048.00, Y=2048.00, Z=0.00, AngleZ=0.00
--- ---
## 2026-05-31 - Per-Instance Client Log Prefixes
### What Changed
- Added a shared local-player log prefix helper for plugin networking logs.
- Prefixed important startup, connection, welcome, transform send, remote update, disconnect, and networking warning logs with `[LocalPlayerId=unassigned]` or `[LocalPlayerId=N]`.
- Kept the existing `Fallout4Together.log` file name and avoided per-instance log files for this milestone.
### What Worked
- The prefix reads the existing assigned player ID state through the thread-safe remote-player state accessor.
- Remote player state storage and packet relay behavior remain unchanged.
### What Broke
- Nothing recorded.
### Notes
- Actor spawning, actor movement, gameplay sync, and protocol changes remain out of scope.
- A future launcher/profile milestone can revisit separate per-instance log files.
### Next Steps
- Test two Fallout 4 instances through F4SE and confirm prefixed remote update/disconnect logs are readable in the shared log file.
---
## Entry Template ## Entry Template
Use this format for future updates: Use this format for future updates:
+2
View File
@@ -1,9 +1,11 @@
#pragma once #pragma once
#include <cstdint> #include <cstdint>
#include <string>
namespace F4T::Networking namespace F4T::Networking
{ {
std::string GetLocalPlayerLogPrefix();
bool ConnectToLocalServer(); bool ConnectToLocalServer();
void DisconnectFromLocalServer(); void DisconnectFromLocalServer();
bool IsConnectedToServer(); bool IsConnectedToServer();
+5 -3
View File
@@ -31,6 +31,7 @@ This means the plugin should be able to:
* Be copied into `Data/F4SE/Plugins/` * Be copied into `Data/F4SE/Plugins/`
* Load when Fallout 4 is launched through F4SE * Load when Fallout 4 is launched through F4SE
* Create or write to a `Fallout4Together.log` file * Create or write to a `Fallout4Together.log` file
* Prefix multiplayer/networking log lines with `[LocalPlayerId=unassigned]` before the server welcome packet and `[LocalPlayerId=N]` after assignment
* Connect to the local server on `127.0.0.1:7777` * Connect to the local server on `127.0.0.1:7777`
* Send local transform packets * Send local transform packets
* Receive `welcome`, `transform`, and `disconnect` packets * Receive `welcome`, `transform`, and `disconnect` packets
@@ -106,9 +107,10 @@ Use this checklist for the first plugin test:
* [ ] Plugin log file is created * [ ] Plugin log file is created
* [ ] Plugin log confirms that the plugin loaded * [ ] Plugin log confirms that the plugin loaded
* [ ] Local server is running before gameplay networking tests * [ ] Local server is running before gameplay networking tests
* [ ] Plugin log shows `Assigned server playerId: N` * [ ] Plugin log shows `[LocalPlayerId=unassigned]` before assignment
* [ ] Plugin logs remote player updates from another connected client * [ ] Plugin log shows `[LocalPlayerId=N] Assigned server playerId: N`
* [ ] Plugin logs remote player removal after a disconnect * [ ] Plugin logs prefixed remote player updates from another connected client
* [ ] Plugin logs prefixed remote player removal after a disconnect
## Notes ## Notes
+59 -21
View File
@@ -68,7 +68,9 @@ namespace
WSADATA winsockData{}; WSADATA winsockData{};
const auto startupResult = WSAStartup(MAKEWORD(2, 2), std::addressof(winsockData)); const auto startupResult = WSAStartup(MAKEWORD(2, 2), std::addressof(winsockData));
if (startupResult != 0) { if (startupResult != 0) {
REX::WARN("Could not initialize Winsock for Fallout 4 Together local networking."); REX::WARN(
"{} Could not initialize Winsock for Fallout 4 Together local networking.",
F4T::Networking::GetLocalPlayerLogPrefix());
return false; return false;
} }
@@ -137,7 +139,7 @@ namespace
void LogThrottledWarning(const std::string& a_key, const char* a_message) void LogThrottledWarning(const std::string& a_key, const char* a_message)
{ {
if (ShouldLogWarning(a_key)) { if (ShouldLogWarning(a_key)) {
REX::WARN("{}", a_message); REX::WARN("{} {}", F4T::Networking::GetLocalPlayerLogPrefix(), a_message);
} }
} }
@@ -238,7 +240,7 @@ namespace
} }
F4T::RemotePlayerState::SetAssignedPlayerId(*playerId); F4T::RemotePlayerState::SetAssignedPlayerId(*playerId);
REX::INFO("Assigned server playerId: {}", *playerId); REX::INFO("{} Assigned server playerId: {}", F4T::Networking::GetLocalPlayerLogPrefix(), *playerId);
} }
void HandleTransformPacket(const Json& a_packet) void HandleTransformPacket(const Json& a_packet)
@@ -281,7 +283,8 @@ namespace
// spawn or move remote actors. The networking thread must not touch actors. // spawn or move remote actors. The networking thread must not touch actors.
if (ShouldLogRemoteUpdate(*playerId)) { if (ShouldLogRemoteUpdate(*playerId)) {
REX::INFO( REX::INFO(
"Remote player {} updated: X={:.2f}, Y={:.2f}, Z={:.2f}, AngleZ={:.2f}, Cell={}, Worldspace={}", "{} Remote player {} updated: X={:.2f}, Y={:.2f}, Z={:.2f}, AngleZ={:.2f}, Cell={}, Worldspace={}",
F4T::Networking::GetLocalPlayerLogPrefix(),
remoteState.playerId, remoteState.playerId,
remoteState.x, remoteState.x,
remoteState.y, remoteState.y,
@@ -303,9 +306,15 @@ namespace
g_lastRemoteUpdateLogTimes.erase(*playerId); g_lastRemoteUpdateLogTimes.erase(*playerId);
if (F4T::RemotePlayerState::RemoveRemotePlayer(*playerId)) { if (F4T::RemotePlayerState::RemoveRemotePlayer(*playerId)) {
REX::INFO("Remote player {} disconnected and was removed.", *playerId); REX::INFO(
"{} Remote player {} disconnected and was removed.",
F4T::Networking::GetLocalPlayerLogPrefix(),
*playerId);
} else { } else {
REX::INFO("Received disconnect for unknown remote player {}.", *playerId); REX::INFO(
"{} Received disconnect for unknown remote player {}.",
F4T::Networking::GetLocalPlayerLogPrefix(),
*playerId);
} }
} }
@@ -313,7 +322,7 @@ namespace
{ {
const auto type = ReadString(a_packet, "type").value_or("<missing>"); const auto type = ReadString(a_packet, "type").value_or("<missing>");
if (ShouldLogWarning("unknown_" + type)) { if (ShouldLogWarning("unknown_" + type)) {
REX::WARN("Ignoring unknown server packet type: {}", type); REX::WARN("{} Ignoring unknown server packet type: {}", F4T::Networking::GetLocalPlayerLogPrefix(), type);
} }
} }
@@ -328,7 +337,10 @@ namespace
packet = Json::parse(a_line); packet = Json::parse(a_line);
} catch (const std::exception& a_error) { } catch (const std::exception& a_error) {
if (ShouldLogWarning("json_parse")) { if (ShouldLogWarning("json_parse")) {
REX::WARN("Ignoring invalid JSON packet from server: {}", a_error.what()); REX::WARN(
"{} Ignoring invalid JSON packet from server: {}",
F4T::Networking::GetLocalPlayerLogPrefix(),
a_error.what());
} }
return; return;
} }
@@ -394,7 +406,9 @@ namespace
} }
if (bytesReceived == 0) { if (bytesReceived == 0) {
REX::WARN("Fallout 4 Together local server closed the connection."); REX::WARN(
"{} Fallout 4 Together local server closed the connection.",
F4T::Networking::GetLocalPlayerLogPrefix());
CloseSocket(); CloseSocket();
break; break;
} }
@@ -406,7 +420,9 @@ namespace
} }
if (g_receiveThreadRunning.load()) { if (g_receiveThreadRunning.load()) {
REX::WARN("Lost connection to Fallout 4 Together local server while receiving."); REX::WARN(
"{} Lost connection to Fallout 4 Together local server while receiving.",
F4T::Networking::GetLocalPlayerLogPrefix());
} }
CloseSocket(); CloseSocket();
break; break;
@@ -440,6 +456,16 @@ namespace
namespace F4T::Networking namespace F4T::Networking
{ {
std::string GetLocalPlayerLogPrefix()
{
const auto assignedPlayerId = F4T::RemotePlayerState::GetAssignedPlayerId();
if (!assignedPlayerId) {
return "[LocalPlayerId=unassigned]";
}
return "[LocalPlayerId=" + std::to_string(*assignedPlayerId) + "]";
}
bool ConnectToLocalServer() bool ConnectToLocalServer()
{ {
if (IsConnectedToServer()) { if (IsConnectedToServer()) {
@@ -458,13 +484,15 @@ namespace F4T::Networking
// packet path without exposing any gameplay state to a remote server. // packet path without exposing any gameplay state to a remote server.
const auto localSocket = socket(AF_INET, SOCK_STREAM, IPPROTO_TCP); const auto localSocket = socket(AF_INET, SOCK_STREAM, IPPROTO_TCP);
if (localSocket == INVALID_SOCKET) { if (localSocket == INVALID_SOCKET) {
REX::WARN("Could not create socket for Fallout 4 Together local server connection."); REX::WARN("{} Could not create socket for Fallout 4 Together local server connection.", GetLocalPlayerLogPrefix());
return false; return false;
} }
if (!SetNonBlocking(localSocket)) { if (!SetNonBlocking(localSocket)) {
closesocket(localSocket); closesocket(localSocket);
REX::WARN("Could not configure non-blocking socket for Fallout 4 Together local server connection."); REX::WARN(
"{} Could not configure non-blocking socket for Fallout 4 Together local server connection.",
GetLocalPlayerLogPrefix());
return false; return false;
} }
@@ -473,7 +501,7 @@ namespace F4T::Networking
serverAddress.sin_port = htons(kLocalServerPort); serverAddress.sin_port = htons(kLocalServerPort);
if (inet_pton(AF_INET, kLocalServerHost, std::addressof(serverAddress.sin_addr)) != 1) { if (inet_pton(AF_INET, kLocalServerHost, std::addressof(serverAddress.sin_addr)) != 1) {
closesocket(localSocket); closesocket(localSocket);
REX::WARN("Could not parse Fallout 4 Together local server address."); REX::WARN("{} Could not parse Fallout 4 Together local server address.", GetLocalPlayerLogPrefix());
return false; return false;
} }
@@ -486,7 +514,11 @@ namespace F4T::Networking
closesocket(localSocket); closesocket(localSocket);
// The server is a developer tool, not a runtime requirement. A failed // The server is a developer tool, not a runtime requirement. A failed
// connection should leave Fallout 4 running and simply disable packet sends. // connection should leave Fallout 4 running and simply disable packet sends.
REX::WARN("Could not connect to Fallout 4 Together local server at 127.0.0.1:7777"); REX::WARN(
"{} Could not connect to Fallout 4 Together local server at {}:{}",
GetLocalPlayerLogPrefix(),
kLocalServerHost,
kLocalServerPort);
return false; return false;
} }
@@ -500,7 +532,11 @@ namespace F4T::Networking
g_lastRemoteUpdateLogTimes.clear(); g_lastRemoteUpdateLogTimes.clear();
StartReceiveThread(); StartReceiveThread();
REX::INFO("Connected to Fallout 4 Together local server."); REX::INFO(
"{} Connected to Fallout 4 Together local server at {}:{}.",
GetLocalPlayerLogPrefix(),
kLocalServerHost,
kLocalServerPort);
return true; return true;
} }
@@ -553,7 +589,7 @@ namespace F4T::Networking
clientTime); clientTime);
if (packetSize <= 0 || static_cast<std::size_t>(packetSize) >= packet.size()) { if (packetSize <= 0 || static_cast<std::size_t>(packetSize) >= packet.size()) {
REX::WARN("Could not format Fallout 4 Together transform packet."); REX::WARN("{} Could not format Fallout 4 Together transform packet.", GetLocalPlayerLogPrefix());
return false; return false;
} }
@@ -566,7 +602,7 @@ namespace F4T::Networking
a_cellId); a_cellId);
if (appended <= 0 || static_cast<std::size_t>(appended) >= remaining) { if (appended <= 0 || static_cast<std::size_t>(appended) >= remaining) {
REX::WARN("Could not format Fallout 4 Together transform packet cell ID."); REX::WARN("{} Could not format Fallout 4 Together transform packet cell ID.", GetLocalPlayerLogPrefix());
return false; return false;
} }
@@ -582,7 +618,9 @@ namespace F4T::Networking
a_worldspaceId); a_worldspaceId);
if (appended <= 0 || static_cast<std::size_t>(appended) >= remaining) { if (appended <= 0 || static_cast<std::size_t>(appended) >= remaining) {
REX::WARN("Could not format Fallout 4 Together transform packet worldspace ID."); REX::WARN(
"{} Could not format Fallout 4 Together transform packet worldspace ID.",
GetLocalPlayerLogPrefix());
return false; return false;
} }
@@ -592,7 +630,7 @@ namespace F4T::Networking
const auto remaining = packet.size() - static_cast<std::size_t>(packetSize); const auto remaining = packet.size() - static_cast<std::size_t>(packetSize);
const auto appended = std::snprintf(packet.data() + packetSize, remaining, "}\n"); const auto appended = std::snprintf(packet.data() + packetSize, remaining, "}\n");
if (appended <= 0 || static_cast<std::size_t>(appended) >= remaining) { if (appended <= 0 || static_cast<std::size_t>(appended) >= remaining) {
REX::WARN("Could not finish Fallout 4 Together transform packet."); REX::WARN("{} Could not finish Fallout 4 Together transform packet.", GetLocalPlayerLogPrefix());
return false; return false;
} }
@@ -611,7 +649,7 @@ namespace F4T::Networking
if (bytesSent == SOCKET_ERROR) { if (bytesSent == SOCKET_ERROR) {
const auto error = WSAGetLastError(); const auto error = WSAGetLastError();
if (error != WSAEWOULDBLOCK) { if (error != WSAEWOULDBLOCK) {
REX::WARN("Lost connection to Fallout 4 Together local server."); REX::WARN("{} Lost connection to Fallout 4 Together local server.", GetLocalPlayerLogPrefix());
CloseSocket(); CloseSocket();
} }
@@ -619,7 +657,7 @@ namespace F4T::Networking
} }
if (bytesSent != packetSize) { if (bytesSent != packetSize) {
REX::WARN("Could not send full Fallout 4 Together transform packet."); REX::WARN("{} Could not send full Fallout 4 Together transform packet.", GetLocalPlayerLogPrefix());
CloseSocket(); CloseSocket();
return false; return false;
} }
+26 -10
View File
@@ -120,7 +120,8 @@ namespace
void LogPlayerTransform(const PlayerTransform& a_transform) void LogPlayerTransform(const PlayerTransform& a_transform)
{ {
REX::INFO("Player position: X={:.2f}, Y={:.2f}, Z={:.2f}, AngleZ={:.2f}", REX::INFO("{} Sent transform: X={:.2f}, Y={:.2f}, Z={:.2f}, AngleZ={:.2f}",
F4T::Networking::GetLocalPlayerLogPrefix(),
a_transform.x, a_transform.x,
a_transform.y, a_transform.y,
a_transform.z, a_transform.z,
@@ -133,7 +134,9 @@ namespace
if (!player) { if (!player) {
static bool playerUnavailableWarningLogged = false; static bool playerUnavailableWarningLogged = false;
if (!playerUnavailableWarningLogged) { if (!playerUnavailableWarningLogged) {
REX::WARN("Player position unavailable: local player reference is not available yet."); REX::WARN(
"{} Player position unavailable: local player reference is not available yet.",
F4T::Networking::GetLocalPlayerLogPrefix());
playerUnavailableWarningLogged = true; playerUnavailableWarningLogged = true;
} }
return; return;
@@ -155,13 +158,19 @@ namespace
const char* movementType = "normal"; const char* movementType = "normal";
if (HasWorldspaceChanged(lastKnownLocation, currentLocation)) { if (HasWorldspaceChanged(lastKnownLocation, currentLocation)) {
REX::INFO("Detected worldspace change. Sending immediate transform update."); REX::INFO(
"{} Detected worldspace change. Sending immediate transform update.",
F4T::Networking::GetLocalPlayerLogPrefix());
movementType = "worldspace_change"; movementType = "worldspace_change";
} else if (HasCellChanged(lastKnownLocation, currentLocation)) { } else if (HasCellChanged(lastKnownLocation, currentLocation)) {
REX::INFO("Detected cell change. Sending immediate transform update."); REX::INFO(
"{} Detected cell change. Sending immediate transform update.",
F4T::Networking::GetLocalPlayerLogPrefix());
movementType = "cell_change"; movementType = "cell_change";
} else if (HasTeleportDistance(lastSentTransform, currentTransform)) { } else if (HasTeleportDistance(lastSentTransform, currentTransform)) {
REX::INFO("Detected teleport/large position jump. Sending immediate transform update."); REX::INFO(
"{} Detected teleport/large position jump. Sending immediate transform update.",
F4T::Networking::GetLocalPlayerLogPrefix());
movementType = "teleport"; movementType = "teleport";
} }
@@ -178,8 +187,7 @@ namespace
// Player transforms can change by tiny amounts every frame. Throttling keeps the // Player transforms can change by tiny amounts every frame. Throttling keeps the
// readout useful for debugging movement without flooding Fallout4Together.log or // readout useful for debugging movement without flooding Fallout4Together.log or
// turning this first local networking test into a packet every frame. // turning this first local networking test into a packet every frame.
LogPlayerTransform(currentTransform); const auto sentTransform = F4T::Networking::SendTransformPacket(
F4T::Networking::SendTransformPacket(
currentTransform.x, currentTransform.x,
currentTransform.y, currentTransform.y,
currentTransform.z, currentTransform.z,
@@ -189,6 +197,9 @@ namespace
currentLocation.cellId, currentLocation.cellId,
currentLocation.hasWorldspaceId, currentLocation.hasWorldspaceId,
currentLocation.worldspaceId); currentLocation.worldspaceId);
if (sentTransform) {
LogPlayerTransform(currentTransform);
}
lastSentTransform = currentTransform; lastSentTransform = currentTransform;
lastKnownLocation = currentLocation; lastKnownLocation = currentLocation;
lastLogTime = currentTime; lastLogTime = currentTime;
@@ -203,7 +214,9 @@ namespace
const auto* taskInterface = F4SE::GetTaskInterface(); const auto* taskInterface = F4SE::GetTaskInterface();
if (!taskInterface) { if (!taskInterface) {
REX::WARN("Failed to get F4SE task interface; player position changes will not be logged."); REX::WARN(
"{} Failed to get F4SE task interface; player position changes will not be logged.",
F4T::Networking::GetLocalPlayerLogPrefix());
return; return;
} }
@@ -240,7 +253,8 @@ F4SE_PLUGIN_LOAD(const F4SE::LoadInterface* a_f4se)
{ {
F4SE::Init(a_f4se); F4SE::Init(a_f4se);
REX::INFO("Fallout 4 Together plugin loaded successfully."); REX::INFO("{} Fallout 4 Together plugin loaded successfully.", F4T::Networking::GetLocalPlayerLogPrefix());
// TODO: Consider separate per-instance log files once launcher/profile support exists.
// Networking is intentionally localhost-only for the first milestone. If the // Networking is intentionally localhost-only for the first milestone. If the
// test server is not running, the game must continue normally and movement // test server is not running, the game must continue normally and movement
@@ -250,7 +264,9 @@ F4SE_PLUGIN_LOAD(const F4SE::LoadInterface* a_f4se)
const auto* messaging = F4SE::GetMessagingInterface(); const auto* messaging = F4SE::GetMessagingInterface();
if (!messaging || !messaging->RegisterListener(OnF4SEMessage)) { if (!messaging || !messaging->RegisterListener(OnF4SEMessage)) {
REX::WARN("Failed to register F4SE message listener; player position will not be logged."); REX::WARN(
"{} Failed to register F4SE message listener; player position will not be logged.",
F4T::Networking::GetLocalPlayerLogPrefix());
} }
return true; return true;