From 21e9ebaaee5fd26390a75379fffcf47f8d890518 Mon Sep 17 00:00:00 2001 From: Daan Vanden Bosch Date: Thu, 5 Aug 2021 15:54:05 +0200 Subject: [PATCH] Improved logging, especially for proxy servers. --- psoserv/README.md | 3 +- .../kotlin/world/phantasmal/psoserv/Main.kt | 16 ++++++-- .../phantasmal/psoserv/servers/GameServer.kt | 9 +++-- .../phantasmal/psoserv/servers/ProxyServer.kt | 31 +++++++++----- .../psoserv/servers/SocketHandler.kt | 40 ++++++++++++------- psoserv/src/main/resources/log4j2.xml | 2 +- 6 files changed, 67 insertions(+), 34 deletions(-) diff --git a/psoserv/README.md b/psoserv/README.md index e0f9ffd1..d5ffbd24 100644 --- a/psoserv/README.md +++ b/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 diff --git a/psoserv/src/main/kotlin/world/phantasmal/psoserv/Main.kt b/psoserv/src/main/kotlin/world/phantasmal/psoserv/Main.kt index 1b31a191..ade80551 100644 --- a/psoserv/src/main/kotlin/world/phantasmal/psoserv/Main.kt +++ b/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 { 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 { 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 + } diff --git a/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/GameServer.kt b/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/GameServer.kt index 085a2319..ff5662c6 100644 --- a/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/GameServer.kt +++ b/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/GameServer.kt @@ -24,8 +24,9 @@ abstract class GameServer( override fun clientConnected(clientSocket: Socket) { // Handle each client connection in its own thread. - val thread = Thread { GameClientHandler(clientSocket).listen() } - thread.name = "${name}_client_${connectionCounter++}" + val client = "${name}_client_${connectionCounter++}" + val thread = Thread { GameClientHandler(client, clientSocket).listen() } + thread.name = client thread.start() } @@ -42,8 +43,8 @@ abstract class GameServer( return true } - private inner class GameClientHandler(socket: Socket) : - SocketHandler(logger, socket) { + private inner class GameClientHandler(client: String, socket: Socket) : + SocketHandler(client, socket) { private val serverCipher = createCipher() private val clientCipher = createCipher() diff --git a/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/ProxyServer.kt b/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/ProxyServer.kt index c054bafb..aaf0046b 100644 --- a/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/ProxyServer.kt +++ b/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.Message -import world.phantasmal.psoserv.messages.MessageDescriptor -import world.phantasmal.psoserv.messages.RedirectMessage +import world.phantasmal.psoserv.messages.* import java.net.Socket class ProxyServer( @@ -31,12 +28,10 @@ class ProxyServer( private inner class ServerHandler( serverSocket: Socket, private val clientSocket: Socket, - ) : SocketHandler(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(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(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." } + } + } } diff --git a/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/SocketHandler.kt b/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/SocketHandler.kt index d64fa7ec..47e761d9 100644 --- a/psoserv/src/main/kotlin/world/phantasmal/psoserv/servers/SocketHandler.kt +++ b/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( - 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( @Volatile private var running = false + protected val logger: KLogger = KotlinLogging.logger(name) protected abstract val messageDescriptor: MessageDescriptor protected abstract val readDecryptCipher: Cipher? @@ -33,7 +35,7 @@ abstract class SocketHandler( 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( when { // Don't parse the message when it's too large. encryptedSize > BUFFER_CAPACITY -> { - logger.warn { - val message = messageString(code, size) - "Receiving $message, too large: ${size}B. Skipping." - } + logMessageTooLarge(code, size) bytesToSkip = encryptedSize - available @@ -111,7 +110,7 @@ abstract class SocketHandler( try { val message = messageDescriptor.readMessage(messageBuffer) - logger.trace { "Received $message." } + logMessageReceived(message) when (processMessage(message)) { ProcessResult.Ok -> { @@ -139,7 +138,7 @@ abstract class SocketHandler( } } } 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( 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( } } } 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( // 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 } diff --git a/psoserv/src/main/resources/log4j2.xml b/psoserv/src/main/resources/log4j2.xml index 597b608c..50c68d13 100644 --- a/psoserv/src/main/resources/log4j2.xml +++ b/psoserv/src/main/resources/log4j2.xml @@ -2,7 +2,7 @@ - +