Improved logging, especially for proxy servers.

psoserv/README.md

@@ -22,7 +22,8 @@ proxy: {
   # One server configuration per address/port pair that needs to be proxied.
   servers: [
     {
-      # Name used for e.g. the logs.
+      # Name used for e.g. the logs. Should contain only alpha-numeric characters, minus (-) or
+      # underscore (_).
       name: patch_proxy
       # PC or BB, determines the message format encryption cipher used.
       version: PC

psoserv/src/main/kotlin/world/phantasmal/psoserv/Main.kt

@@ -114,7 +114,7 @@ private fun initialize(config: Config): PhantasmalServer {
 
         config.blocks.filter { it.run }.associate { blockCfg ->
             val block = BlockInfo(
-                name = blockCfg.name ?: "block_$blockI",
+                name = validateName("Block", blockCfg.name) ?: "block_$blockI",
                 uiName = blockCfg.uiName ?: "BLOCK${blockI.toString(2).padStart(2, '0')}",
                 bindPair = Inet4Pair(
                     blockCfg.address?.let(::inet4Address) ?: defaultAddress,
@@ -132,7 +132,7 @@ private fun initialize(config: Config): PhantasmalServer {
 
         shipsToRun.map { shipCfg ->
             val ship = ShipInfo(
-                name = shipCfg.name ?: "ship_$shipI",
+                name = validateName("Ship", shipCfg.name) ?: "ship_$shipI",
                 uiName = shipCfg.uiName ?: "Ship $shipI",
                 bindPair = Inet4Pair(
                     shipCfg.address?.let(::inet4Address) ?: defaultAddress,
@@ -256,7 +256,7 @@ private fun initializeProxy(config: ProxyConfig): List<ProxyServer> {
             continue
         }
 
-        val name = psc.name ?: "proxy_${nameI++}"
+        val name = validateName("Proxy server", psc.name) ?: "proxy_${nameI++}"
         val bindPair = Inet4Pair(
             psc.bindAddress?.let(::inet4Address) ?: defaultBindAddress,
             psc.bindPort,
@@ -299,3 +299,13 @@ private fun initializeProxy(config: ProxyConfig): List<ProxyServer> {
 
     return proxyServers
 }
+
+private fun validateName(whichName: String, name: String?): String? =
+    if (name == null) {
+        null
+    } else {
+        check(Regex("[a-zA-Z0-9_-]+").matches(name)) {
+            """$whichName name "$name" should contain only alpha-numeric characters, minus (-) or underscore (_)."""
+        }
+        name
+    }

psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/GameServer.kt

@@ -24,8 +24,9 @@ abstract class GameServer<MessageType : Message>(
 
     override fun clientConnected(clientSocket: Socket) {
         // Handle each client connection in its own thread.
-        val thread = Thread { GameClientHandler(clientSocket).listen() }
+        val client = "${name}_client_${connectionCounter++}"
-        thread.name = "${name}_client_${connectionCounter++}"
+        val thread = Thread { GameClientHandler(client, clientSocket).listen() }
+        thread.name = client
         thread.start()
     }
 
@@ -42,8 +43,8 @@ abstract class GameServer<MessageType : Message>(
         return true
     }
 
-    private inner class GameClientHandler(socket: Socket) :
+    private inner class GameClientHandler(client: String, socket: Socket) :
-        SocketHandler<MessageType>(logger, socket) {
+        SocketHandler<MessageType>(client, socket) {
 
         private val serverCipher = createCipher()
         private val clientCipher = createCipher()

psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/ProxyServer.kt

@@ -2,10 +2,7 @@ package world.phantasmal.psoserv.servers
 
 import world.phantasmal.psolib.buffer.Buffer
 import world.phantasmal.psoserv.encryption.Cipher
-import world.phantasmal.psoserv.messages.InitEncryptionMessage
+import world.phantasmal.psoserv.messages.*
-import world.phantasmal.psoserv.messages.Message
-import world.phantasmal.psoserv.messages.MessageDescriptor
-import world.phantasmal.psoserv.messages.RedirectMessage
 import java.net.Socket
 
 class ProxyServer(
@@ -31,12 +28,10 @@ class ProxyServer(
     private inner class ServerHandler(
         serverSocket: Socket,
         private val clientSocket: Socket,
-    ) : SocketHandler<Message>(logger, serverSocket) {
+    ) : ProxySocketHandler("${name}_server", serverSocket) {
 
         private var clientHandler: ClientHandler? = null
 
-        override val messageDescriptor = this@ProxyServer.messageDescriptor
-
         // The first message sent by the server is always unencrypted and initializes the
         // encryption. We don't start listening to the client until the encryption is
         // initialized.
@@ -66,7 +61,7 @@ class ProxyServer(
                     )
                     this.clientHandler = clientListener
                     val thread = Thread(clientListener::listen)
-                    thread.name = "$name client"
+                    thread.name = "${name}_client"
                     thread.start()
                 }
 
@@ -104,9 +99,8 @@ class ProxyServer(
         private val serverHandler: ServerHandler,
         override val readDecryptCipher: Cipher,
         override val readEncryptCipher: Cipher,
-    ) : SocketHandler<Message>(logger, clientSocket) {
+    ) : ProxySocketHandler("${name}_client", clientSocket) {
 
-        override val messageDescriptor = this@ProxyServer.messageDescriptor
         override val writeEncryptCipher: Cipher? = null
 
         override fun processMessage(message: Message): ProcessResult = ProcessResult.Ok
@@ -119,4 +113,21 @@ class ProxyServer(
             serverHandler.stop()
         }
     }
+
+    private abstract inner class ProxySocketHandler(name: String, socket: Socket) :
+        SocketHandler<Message>(name, socket) {
+
+        override val messageDescriptor = this@ProxyServer.messageDescriptor
+
+        override fun logMessageTooLarge(code: Int, size: Int) {
+            logger.warn {
+                val message = messageString(code, size)
+                "Sending $message with size ${size}B. Skipping because it's too large."
+            }
+        }
+
+        override fun logMessageReceived(message: Message) {
+            logger.trace { "Sent $message." }
+        }
+    }
 }

psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/SocketHandler.kt

@@ -1,19 +1,20 @@
 package world.phantasmal.psoserv.servers
 
 import mu.KLogger
+import mu.KotlinLogging
 import world.phantasmal.psolib.Endianness
 import world.phantasmal.psolib.buffer.Buffer
+import world.phantasmal.psoserv.alignToWidth
 import world.phantasmal.psoserv.encryption.Cipher
 import world.phantasmal.psoserv.messages.Message
 import world.phantasmal.psoserv.messages.MessageDescriptor
 import world.phantasmal.psoserv.messages.messageString
-import world.phantasmal.psoserv.alignToWidth
 import java.net.Socket
 import java.net.SocketException
 import kotlin.math.min
 
 abstract class SocketHandler<MessageType : Message>(
-    protected val logger: KLogger,
+    protected val name: String,
     private val socket: Socket,
 ) {
     private val sockName: String = "${socket.remoteSocketAddress}"
@@ -22,6 +23,7 @@ abstract class SocketHandler<MessageType : Message>(
     @Volatile
     private var running = false
 
+    protected val logger: KLogger = KotlinLogging.logger(name)
     protected abstract val messageDescriptor: MessageDescriptor<MessageType>
     protected abstract val readDecryptCipher: Cipher?
 
@@ -33,7 +35,7 @@ abstract class SocketHandler<MessageType : Message>(
     protected abstract val writeEncryptCipher: Cipher?
 
     fun listen() {
-        logger.info { "Listening to $sockName." }
+        logger.info { "Listening to $name ($sockName)." }
         running = true
 
         try {
@@ -76,10 +78,7 @@ abstract class SocketHandler<MessageType : Message>(
                     when {
                         // Don't parse the message when it's too large.
                         encryptedSize > BUFFER_CAPACITY -> {
-                            logger.warn {
+                            logMessageTooLarge(code, size)
-                                val message = messageString(code, size)
-                                "Receiving $message, too large: ${size}B. Skipping."
-                            }
 
                             bytesToSkip = encryptedSize - available
 
@@ -111,7 +110,7 @@ abstract class SocketHandler<MessageType : Message>(
 
                             try {
                                 val message = messageDescriptor.readMessage(messageBuffer)
-                                logger.trace { "Received $message." }
+                                logMessageReceived(message)
 
                                 when (processMessage(message)) {
                                     ProcessResult.Ok -> {
@@ -139,7 +138,7 @@ abstract class SocketHandler<MessageType : Message>(
                                     }
                                 }
                             } catch (e: Throwable) {
-                                logger.error(e) { "Error while processing message from $sockName." }
+                                logger.error(e) { "Error while processing message." }
                             }
 
                             offset += encryptedSize
@@ -161,7 +160,7 @@ abstract class SocketHandler<MessageType : Message>(
 
                         if (read == -1) {
                             logger.warn {
-                                "Expected to skip $bytesToSkip more bytes, but $sockName stopped sending."
+                                "Expected to skip $bytesToSkip more bytes, but $name stopped sending."
                             }
 
                             // Close the connection.
@@ -189,23 +188,23 @@ abstract class SocketHandler<MessageType : Message>(
                 }
             }
         } catch (e: InterruptedException) {
-            logger.error(e) { "Interrupted while listening to $sockName, closing connection." }
+            logger.error(e) { "Interrupted while listening to $name ($sockName), closing connection." }
         } catch (e: SocketException) {
             // Don't log if we're not running anymore because that means this exception was probably
             // generated by a socket.close() call.
             if (running) {
-                logger.error(e) { "Error while listening to $sockName, closing connection." }
+                logger.error(e) { "Error while listening to $name ($sockName), closing connection." }
             }
         } catch (e: Throwable) {
-            logger.error(e) { "Error while listening to $sockName, closing connection." }
+            logger.error(e) { "Error while listening to $name ($sockName), closing connection." }
         } finally {
             running = false
 
             try {
                 if (socket.isClosed) {
-                    logger.info { "Connection to $sockName was closed." }
+                    logger.info { "Connection to $name ($sockName) was closed." }
                 } else {
-                    logger.info { "Closing connection to $sockName." }
+                    logger.info { "Closing connection to $name ($sockName)." }
                     socket.close()
                 }
             } finally {
@@ -262,6 +261,17 @@ abstract class SocketHandler<MessageType : Message>(
         // Do nothing.
     }
 
+    protected open fun logMessageTooLarge(code: Int, size: Int) {
+        logger.warn {
+            val message = messageString(code, size)
+            "Receiving $message with size ${size}B. Skipping because it's too large."
+        }
+    }
+
+    protected open fun logMessageReceived(message: Message) {
+        logger.trace { "Received $message." }
+    }
+
     protected enum class ProcessResult {
         Ok, Changed, Done
     }

psoserv/src/main/resources/log4j2.xml

@@ -2,7 +2,7 @@
 <Configuration status="WARN">
     <Appenders>
         <Console name="Console" target="SYSTEM_OUT">
-            <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %logger{36} [%t] - %msg%n"/>
+            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%-5level] %logger{36} - %msg%n"/>
         </Console>
     </Appenders>
     <Loggers>