More info logging (#951)

* Add more session info to messages and promote some from debug to info

* Show malformed section of data in malformed game stats log message

* Add game id to GameConnection logger name

* Add exception message to log message for some errors

This makes it easier to distinguish what errors are worth looking into 
in grafana as when you filter for 'ERROR' you don't see the exception 
trace.

* Log UnicodeDecodeErrors separately to include section of malformed data

server/gameconnection.py

@@ -5,6 +5,7 @@
 import asyncio
 import contextlib
 import json
+import logging
 from typing import Any
 
 from sqlalchemy import select
@@ -13,7 +14,6 @@
 
 from .config import TRACE
 from .db.models import coop_leaderboard, coop_map, teamkills
-from .decorators import with_logger
 from .game_service import GameService
 from .games import (
     CoopGame,
@@ -30,7 +30,6 @@
 from .protocol import DisconnectedError, GpgNetServerProtocol, Protocol
 
 
-@with_logger
 class GameConnection(GpgNetServerProtocol):
     """
     Responsible for connections to the game, using the GPGNet protocol
@@ -50,6 +49,9 @@ def __init__(
         Construct a new GameConnection
         """
         super().__init__()
+        self._logger = logging.getLogger(
+            f"{self.__class__.__qualname__}.{game.id}"
+        )
         self._db = database
         self._logger.debug("GameConnection initializing")
 
@@ -212,8 +214,11 @@ async def handle_action(self, command: str, args: list[Any]):
             self._logger.exception("Bad command arguments")
         except ConnectionError as e:
             raise e
-        except Exception:  # pragma: no cover
-            self._logger.exception("Something awful happened in a game thread!")
+        except Exception as e:  # pragma: no cover
+            self._logger.exception(
+                "Something awful happened in a game thread! %s",
+                e
+            )
             await self.abort()
 
     async def handle_desync(self, *_args):  # pragma: no cover
@@ -362,11 +367,11 @@ async def handle_operation_complete(
     async def handle_json_stats(self, stats: str):
         try:
             self.game.report_army_stats(stats)
-        except json.JSONDecodeError:
+        except json.JSONDecodeError as e:
             self._logger.warning(
-                "Malformed game stats reported by %s: '...%s'",
+                "Malformed game stats reported by %s: '...%s...'",
                 self._player.login,
-                stats[-20:]
+                stats[e.pos-20:e.pos+20]
             )
 
     async def handle_enforce_rating(self):

server/lobbyconnection.py

@@ -97,7 +97,7 @@ def __init__(
 
         self._attempted_connectivity_test = False
 
-        self._logger.debug("LobbyConnection initialized")
+        self._logger.debug("LobbyConnection initialized for '%s'", self.session)
 
     @property
     def authenticated(self):
@@ -118,9 +118,10 @@ async def on_connection_made(self, protocol: Protocol, peername: Address):
     async def abort(self, logspam=""):
         self._authenticated = False
 
-        identity = self.player.login if self.player else self.peer_address.host
         self._logger.warning(
-            "Aborting connection for %s. %s", identity, logspam
+            "Aborting connection for '%s'. %s",
+            self.get_user_identifier(),
+            logspam
         )
 
         if self.game_connection:
@@ -562,8 +563,12 @@ async def on_player_login(
         if not conforms_policy:
             return
 
-        self._logger.debug(
-            "Login from: %s, %s, %s, %s", player_id, username, method, self.session
+        self._logger.info(
+            "Login from: %s(id=%s), using method '%s' for session %s",
+            username,
+            player_id,
+            method,
+            self.session
         )
         metrics.user_logins.labels("success", method).inc()
 

server/servercontext.py

@@ -114,16 +114,19 @@ def write_broadcast_raw(self, data, validate_fn=lambda _: True):
                 )
 
     async def client_connected(self, stream_reader, stream_writer):
-        self._logger.debug("%s: Client connected", self.name)
+        peername = Address(*stream_writer.get_extra_info("peername"))
+        self._logger.info(
+            "%s: Client connected from %s:%s",
+            self.name,
+            peername.host,
+            peername.port
+        )
         protocol = self.protocol_class(stream_reader, stream_writer)
         connection = self._connection_factory()
         self.connections[connection] = protocol
 
         try:
-            await connection.on_connection_made(
-                protocol,
-                Address(*stream_writer.get_extra_info("peername"))
-            )
+            await connection.on_connection_made(protocol, peername)
             metrics.user_connections.labels("None", "None").inc()
             while protocol.is_connected():
                 message = await protocol.read_message()
@@ -136,11 +139,20 @@ async def client_connected(self, stream_reader, stream_writer):
             asyncio.CancelledError,
         ):
             pass
-        except Exception:
+        except UnicodeDecodeError as e:
             self._logger.exception(
-                "%s: Exception in protocol for '%s'",
+                "%s: Unicode error in protocol for '%s': %s '...%s...'",
                 self.name,
-                connection.get_user_identifier()
+                connection.get_user_identifier(),
+                e,
+                e.object[e.start-20:e.end+20]
+            )
+        except Exception as e:
+            self._logger.exception(
+                "%s: Exception in protocol for '%s': %s",
+                self.name,
+                connection.get_user_identifier(),
+                e
             )
         finally:
             del self.connections[connection]
@@ -154,7 +166,7 @@ async def client_connected(self, stream_reader, stream_writer):
             with self.suppress_and_log(connection.on_connection_lost, Exception):
                 await connection.on_connection_lost()
 
-            self._logger.debug(
+            self._logger.info(
                 "%s: Client disconnected for '%s'",
                 self.name,
                 connection.get_user_identifier()