From 2d8b613a3ad48acafd683f5286e29c3f1c167275 Mon Sep 17 00:00:00 2001 From: Sho Sakuma Date: Mon, 3 Aug 2026 00:40:30 +0900 Subject: perf: take per-message logging off the chat path Every channel message wrote a fully interpolated INFO line, duplicating what the dedicated async ChannelMessageLogger already persists. Every cross-server message produced one INFO on the sending Paper server, two on Velocity, and one on each receiving Paper server - so a single global chat message cost up to four synchronous console and latest.log writes across the network, on the message path, with JUL and Logback appenders being synchronous. These are now debug, and phrased so the string is not built unless debug is on: the JUL sites take a supplier, the slf4j sites take a format plus arguments. Handshake, registration and delivery-failure lines stay at info - they fire once per server or once per failed message, and they explain something an operator needs to see. Two relay tests asserted on the text of a log line. One of them was verifying "0 servers" where the same test already verifies zero sends; the other was really checking that the payload reaches the target, so it now decodes the relayed bytes and compares them to the original message. Co-Authored-By: Claude --- .../paper/chat/handler/ChannelMessageHandler.kt | 2 +- .../paper/velocity/CrossServerChatManager.kt | 8 ++++---- .../velocity/CrossServerDirectMessageManager.kt | 6 +++--- .../velocity/messaging/CrossServerChatRelay.kt | 9 ++++++--- .../messaging/CrossServerDirectMessageRelay.kt | 10 +++++++--- .../velocity/messaging/PluginMessageHandler.kt | 8 +++++--- .../velocity/messaging/CrossServerChatRelayTest.kt | 20 +++++++++----------- 7 files changed, 35 insertions(+), 28 deletions(-) diff --git a/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/chat/handler/ChannelMessageHandler.kt b/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/chat/handler/ChannelMessageHandler.kt index 985f321..4cfd061 100644 --- a/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/chat/handler/ChannelMessageHandler.kt +++ b/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/chat/handler/ChannelMessageHandler.kt @@ -75,7 +75,7 @@ class ChannelMessageHandler( } } - logger.info("Channel Message from ${player.name} in ${context.channel.name}: $message") + logger.debug("Channel Message from {} in {}: {}", player.name, context.channel.name, message) // Log message to file if logging is enabled messageLogger?.let { diff --git a/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/velocity/CrossServerChatManager.kt b/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/velocity/CrossServerChatManager.kt index 2f2bde0..19668be 100644 --- a/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/velocity/CrossServerChatManager.kt +++ b/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/velocity/CrossServerChatManager.kt @@ -69,7 +69,7 @@ class CrossServerChatManager( PluginMessageChannel.ID, PluginMessageCodec.encode(globalChatMessage), ) - logger.info("Sent global chat message to Velocity: messageId=$messageId, player=$playerName") + logger.fine { "Sent global chat message to Velocity: messageId=$messageId, player=$playerName" } } else { logger.warning("Cannot send global chat message: player $playerId not found") } @@ -109,10 +109,10 @@ class CrossServerChatManager( }, ) - logger.info( + logger.fine { "Broadcasted global chat message from ${message.serverName}: " + - "player=${message.playerName}, messageId=${message.messageId}", - ) + "player=${message.playerName}, messageId=${message.messageId}" + } } catch (e: Exception) { logger.log(Level.SEVERE, "Failed to handle incoming global chat message", e) } diff --git a/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/velocity/CrossServerDirectMessageManager.kt b/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/velocity/CrossServerDirectMessageManager.kt index b35f6a5..76cc879 100644 --- a/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/velocity/CrossServerDirectMessageManager.kt +++ b/platform-paper/src/main/kotlin/dev/m1sk9/lunaticChat/paper/velocity/CrossServerDirectMessageManager.kt @@ -69,10 +69,10 @@ class CrossServerDirectMessageManager( ) sender.sendPluginMessage(plugin, PluginMessageChannel.ID, PluginMessageCodec.encode(relay)) - logger.info( + logger.fine { "Sent direct message to Velocity: messageId=$messageId, " + - "target=$targetName@$targetServerName", - ) + "target=$targetName@$targetServerName" + } } catch (e: Exception) { logger.log(Level.SEVERE, "Failed to send cross-server direct message", e) } diff --git a/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerChatRelay.kt b/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerChatRelay.kt index f47db70..bebc7b9 100644 --- a/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerChatRelay.kt +++ b/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerChatRelay.kt @@ -43,9 +43,12 @@ class CrossServerChatRelay( relayCount++ } - logger.info( - "Relayed global chat message from ${message.serverName} to $relayCount servers " + - "(messageId=${message.messageId}, player=${message.playerName})", + logger.debug( + "Relayed global chat message from {} to {} servers (messageId={}, player={})", + message.serverName, + relayCount, + message.messageId, + message.playerName, ) } catch (e: Exception) { logger.error("Failed to relay global chat message: ${e.message}", e) diff --git a/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerDirectMessageRelay.kt b/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerDirectMessageRelay.kt index 3746395..f9cc52d 100644 --- a/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerDirectMessageRelay.kt +++ b/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerDirectMessageRelay.kt @@ -62,9 +62,13 @@ class CrossServerDirectMessageRelay( } targetServer.sendPluginMessage(CHANNEL, PluginMessageCodec.encode(message)) - logger.info( - "Relayed direct message from ${message.senderName}@${message.sourceServerName} " + - "to ${message.targetName}@${message.targetServerName} (messageId=${message.messageId})", + logger.debug( + "Relayed direct message from {}@{} to {}@{} (messageId={})", + message.senderName, + message.sourceServerName, + message.targetName, + message.targetServerName, + message.messageId, ) } catch (e: Exception) { logger.error("Failed to relay direct message: ${e.message}", e) diff --git a/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/PluginMessageHandler.kt b/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/PluginMessageHandler.kt index 6b40a7e..aa0cc07 100644 --- a/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/PluginMessageHandler.kt +++ b/platform-velocity/src/main/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/PluginMessageHandler.kt @@ -170,9 +170,11 @@ class PluginMessageHandler( connection: ServerConnection, message: PluginMessage.GlobalChatMessage, ) { - logger.info( - "Received global chat message from ${connection.serverInfo.name}: " + - "messageId=${message.messageId}, player=${message.playerName}", + logger.debug( + "Received global chat message from {}: messageId={}, player={}", + connection.serverInfo.name, + message.messageId, + message.playerName, ) crossServerChatRelay.relayGlobalMessage(message, connection.server) diff --git a/platform-velocity/src/test/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerChatRelayTest.kt b/platform-velocity/src/test/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerChatRelayTest.kt index 50b0db2..1cd5fbf 100644 --- a/platform-velocity/src/test/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerChatRelayTest.kt +++ b/platform-velocity/src/test/kotlin/dev/m1sk9/lunaticChat/velocity/messaging/CrossServerChatRelayTest.kt @@ -4,11 +4,14 @@ import com.velocitypowered.api.proxy.ProxyServer import com.velocitypowered.api.proxy.messages.ChannelIdentifier import com.velocitypowered.api.proxy.server.RegisteredServer import dev.m1sk9.lunaticChat.engine.protocol.PluginMessage +import dev.m1sk9.lunaticChat.engine.protocol.PluginMessageCodec import io.mockk.every import io.mockk.mockk +import io.mockk.slot import io.mockk.verify import org.slf4j.Logger import kotlin.test.Test +import kotlin.test.assertEquals class CrossServerChatRelayTest { private fun createRelay(): Triple { @@ -70,7 +73,7 @@ class CrossServerChatRelayTest { @Test fun `relayGlobalMessage with only source server should relay to zero`() { - val (relay, proxyServer, logger) = createRelay() + val (relay, proxyServer, _) = createRelay() val sourceServer = createRegisteredServer("lobby") every { proxyServer.allServers } returns listOf(sourceServer) @@ -78,27 +81,22 @@ class CrossServerChatRelayTest { relay.relayGlobalMessage(createTestMessage(), sourceServer) verify(exactly = 0) { sourceServer.sendPluginMessage(any(), any()) } - verify { logger.info(match { it.contains("0 servers") }) } } @Test - fun `relayGlobalMessage should log with messageId and playerName`() { - val (relay, proxyServer, logger) = createRelay() + fun `relayGlobalMessage should forward the message unchanged`() { + val (relay, proxyServer, _) = createRelay() val sourceServer = createRegisteredServer("lobby") val targetServer = createRegisteredServer("survival") + val relayed = slot() every { proxyServer.allServers } returns listOf(sourceServer, targetServer) + every { targetServer.sendPluginMessage(any(), capture(relayed)) } returns true val message = createTestMessage(messageId = "test-msg-123") relay.relayGlobalMessage(message, sourceServer) - verify { - logger.info( - match { msg -> - msg.contains("test-msg-123") && msg.contains("TestPlayer") - }, - ) - } + assertEquals(message, PluginMessageCodec.decode(relayed.captured)) } @Test -- cgit v1.2.1