allnet: enhance logging

core/allnet.py

@@ -171,7 +171,7 @@ class AllnetServlet:
         if machine is None and not self.config.server.allow_unregistered_serials:
             msg = f"Unrecognised serial {req.serial} attempted allnet auth from {request_ip}."
             await self.data.base.log_event(
-                "allnet", "ALLNET_AUTH_UNKNOWN_SERIAL", logging.WARN, msg
+                "allnet", "ALLNET_AUTH_UNKNOWN_SERIAL", logging.WARN, msg, {"serial": req.serial}, None, None, None, request_ip, req.game_id, req.ver
             )
             self.logger.warning(msg)
 
@@ -183,9 +183,9 @@ class AllnetServlet:
             arcade = await self.data.arcade.get_arcade(machine["arcade"])
             if self.config.server.check_arcade_ip:
                 if arcade["ip"] and arcade["ip"] is not None and arcade["ip"] != req.ip:
-                    msg = f"Serial {req.serial} attempted allnet auth from bad IP {req.ip} (expected {arcade['ip']})."
+                    msg = f"{req.serial} attempted allnet auth from bad IP {req.ip} (expected {arcade['ip']})."
                     await self.data.base.log_event(
-                        "allnet", "ALLNET_AUTH_BAD_IP", logging.ERROR, msg
+                        "allnet", "ALLNET_AUTH_BAD_IP", logging.ERROR, msg, {}, None, arcade['id'], machine['id'], request_ip, req.game_id, req.ver
                     )
                     self.logger.warning(msg)
 
@@ -194,9 +194,9 @@ class AllnetServlet:
                     return PlainTextResponse(urllib.parse.unquote(urllib.parse.urlencode(resp_dict)) + "\n")
                 
                 elif (not arcade["ip"] or arcade["ip"] is None) and self.config.server.strict_ip_checking:
-                    msg = f"Serial {req.serial} attempted allnet auth from bad IP {req.ip}, but arcade {arcade['id']} has no IP set! (strict checking enabled)."
+                    msg = f"{req.serial} attempted allnet auth from bad IP {req.ip}, but arcade {arcade['id']} has no IP set! (strict checking enabled)."
                     await self.data.base.log_event(
-                        "allnet", "ALLNET_AUTH_NO_SHOP_IP", logging.ERROR, msg
+                        "allnet", "ALLNET_AUTH_NO_SHOP_IP", logging.ERROR, msg, {}, None, arcade['id'], machine['id'], request_ip, req.game_id, req.ver
                     )
                     self.logger.warning(msg)
 
@@ -204,6 +204,16 @@ class AllnetServlet:
                     resp_dict = {k: v for k, v in vars(resp).items() if v is not None}
                     return PlainTextResponse(urllib.parse.unquote(urllib.parse.urlencode(resp_dict)) + "\n")
 
+            if machine['game'] and machine['game'] != req.game_id:
+                msg = f"{req.serial} attempted allnet auth with bad game ID {req.game_id} (expected {machine['game']})."
+                await self.data.base.log_event(
+                    "allnet", "ALLNET_AUTH_BAD_GAME", logging.ERROR, msg, {}, None, arcade['id'], machine['id'], request_ip, req.game_id, req.ver
+                )
+                self.logger.warning(msg)
+
+                resp.stat = ALLNET_STAT.bad_game.value
+                resp_dict = {k: v for k, v in vars(resp).items() if v is not None}
+                return PlainTextResponse(urllib.parse.unquote(urllib.parse.urlencode(resp_dict)) + "\n")
             
             country = (
                 arcade["country"] if machine["country"] is None else machine["country"]
@@ -236,11 +246,14 @@ class AllnetServlet:
                 arcade["timezone"] if arcade["timezone"] is not None else "+0900" if req.format_ver == 3 else "+09:00"
             )
         
+        else:
+            arcade = None
+
         if req.game_id not in TitleServlet.title_registry:
             if not self.config.server.is_develop:
                 msg = f"Unrecognised game {req.game_id} attempted allnet auth from {request_ip}."
                 await self.data.base.log_event(
-                    "allnet", "ALLNET_AUTH_UNKNOWN_GAME", logging.WARN, msg
+                    "allnet", "ALLNET_AUTH_UNKNOWN_GAME", logging.WARN, msg, {}, None, arcade['id'] if arcade else None, machine['id'] if machine else None, request_ip, req.game_id, req.ver
                 )
                 self.logger.warning(msg)
 
@@ -271,8 +284,17 @@ class AllnetServlet:
             resp_dict = {k: v for k, v in vars(resp).items() if v is not None}
             return PlainTextResponse(urllib.parse.unquote(urllib.parse.urlencode(resp_dict)) + "\n")
 
+        if machine and arcade:
             msg = f"{req.serial} authenticated from {request_ip}: {req.game_id} v{req.ver}"
-        await self.data.base.log_event("allnet", "ALLNET_AUTH_SUCCESS", logging.INFO, msg)
+            await self.data.base.log_event(
+                "allnet", "ALLNET_AUTH_SUCCESS", logging.INFO, msg, {}, None, arcade['id'], machine['id'], request_ip, req.game_id, req.ver
+                )
+        else:
+            msg = f"Allow unregistered serial {req.serial} to authenticate from {request_ip}: {req.game_id} v{req.ver}"
+            await self.data.base.log_event(
+                "allnet", "ALLNET_AUTH_SUCCESS_UNREG", logging.INFO, msg, {"serial": req.serial}, None, None, None, request_ip, req.game_id, req.ver
+                )
+        
         self.logger.info(msg)
 
         resp_dict = {k: v for k, v in vars(resp).items() if v is not None}
@@ -329,7 +351,11 @@ class AllnetServlet:
         ):
             return PlainTextResponse(urllib.parse.unquote(urllib.parse.urlencode(vars(resp))) + "\n")
 
-        else:  # TODO: Keychip check
+        else:
+            machine = await self.data.arcade.get_machine(req.serial)
+            if not machine or not machine['ota_enable'] or not machine['is_cab'] or machine['is_blacklisted']:
+                return PlainTextResponse(urllib.parse.unquote(urllib.parse.urlencode(vars(resp))) + "\n")
+
             if path.exists(
                 f"{self.config.allnet.update_cfg_folder}/{req.game_id}-{req.ver.replace('.', '')}-app.ini"
             ):
@@ -340,8 +366,13 @@ class AllnetServlet:
             ):
                 resp.uri += f"|http://{self.config.server.hostname}:{self.config.server.port}/dl/ini/{req.game_id}-{req.ver.replace('.', '')}-opt.ini"
 
-            self.logger.debug(f"Sending download uri {resp.uri}")
+            if resp.uri:
-            await self.data.base.log_event("allnet", "DLORDER_REQ_SUCCESS", logging.INFO, f"{Utils.get_ip_addr(request)} requested DL Order for {req.serial} {req.game_id} v{req.ver}")
+                self.logger.info(f"Sending download uri {resp.uri}")
+                await self.data.base.log_event(
+                    "allnet", "DLORDER_REQ_SUCCESS", logging.INFO, f"Send download URI to {req.serial} for {req.game_id} v{req.ver} from {Utils.get_ip_addr(request)}", {"uri": resp.uri}, None,
+                    machine['arcade'], machine['id'], request_ip, req.game_id, req.ver
+                )
+            # Maybe add a log event for checkin but no url sent?
 
             res_str = urllib.parse.unquote(urllib.parse.urlencode(vars(resp))) + "\n"
             
@@ -357,13 +388,16 @@ class AllnetServlet:
 
     async def handle_dlorder_ini(self, request: Request) -> bytes:
         req_file = request.path_params.get("file", "").replace("%0A", "").replace("\n", "")
+        request_ip = Utils.get_ip_addr(request)
 
         if not req_file:
             return PlainTextResponse(status_code=404)
 
         if path.exists(f"{self.config.allnet.update_cfg_folder}/{req_file}"):
-            self.logger.info(f"Request for DL INI file {req_file} from {Utils.get_ip_addr(request)} successful")
+            self.logger.info(f"Request for DL INI file {req_file} from {request_ip} successful")
-            await self.data.base.log_event("allnet", "DLORDER_INI_SENT", logging.INFO, f"{Utils.get_ip_addr(request)} successfully recieved {req_file}")
+            await self.data.base.log_event(
+                "allnet", "DLORDER_INI_SENT", logging.INFO, f"{request_ip} successfully recieved {req_file}", {"file": req_file}, ip=request_ip
+            )
             
             return PlainTextResponse(open(
                 f"{self.config.allnet.update_cfg_folder}/{req_file}", "r", encoding="utf-8"
@@ -401,7 +435,13 @@ class AllnetServlet:
         msg = f"{rep.serial} @ {client_ip} reported {rep.rep_type.name} download state {rep.rf_state.name} for {rep.gd} v{rep.dav}:"\
               f" {rep.tdsc}/{rep.tsc} segments downloaded for working files {rep.wfl} with {rep.dfl if rep.dfl else 'none'} complete."
         
-        await self.data.base.log_event("allnet", "DL_REPORT", logging.INFO, msg, dl_data)
+        machine = await self.data.arcade.get_machine(rep.serial)
+        if machine:
+            await self.data.base.log_event("allnet", "DL_REPORT", logging.INFO, msg, dl_data, None, machine['arcade'], machine['id'], client_ip, rep.gd, rep.dav)
+        
+        else:
+            msg = "Unknown serial " + msg
+            await self.data.base.log_event("allnet", "DL_REPORT_UNREG", logging.INFO, msg, dl_data, None, None, None, client_ip, rep.gd, rep.dav)
         self.logger.info(msg)
 
         return PlainTextResponse("OK")
@@ -421,14 +461,24 @@ class AllnetServlet:
         if serial is None or num_files_dld is None or num_files_to_dl is None or dl_state is None:
             return PlainTextResponse("NG")
 
-        self.logger.info(f"LoaderStateRecorder Request from {ip} {serial}: {num_files_dld}/{num_files_to_dl} Files download (State: {dl_state})")
+        msg = f"LoaderStateRecorder Request from {ip} {serial}: {num_files_dld}/{num_files_to_dl} Files download (State: {dl_state})"
+        machine = await self.data.arcade.get_machine(serial)
+        if machine:
+            await self.data.base.log_event("allnet", "LSR_REPORT", logging.INFO, msg, req_dict, None, machine['arcade'], machine['id'], ip)
+        
+        else:
+            msg = "Unregistered " + msg
+            await self.data.base.log_event("allnet", "LSR_REPORT_UNREG", logging.INFO, msg, req_dict, None, None, None, ip)
+        
+        self.logger.info(msg)
         return PlainTextResponse("OK")
     
     async def handle_alive(self, request: Request) -> bytes:
         return PlainTextResponse("OK")
 
     async def handle_naomitest(self, request: Request) -> bytes:
-        self.logger.info(f"Ping from {Utils.get_ip_addr(request)}")
+        # This could be spam-able, removing
+        #self.logger.info(f"Ping from {Utils.get_ip_addr(request)}")
         return PlainTextResponse("naomi ok")
 
     def allnet_req_to_dict(self, data: str) -> Optional[List[Dict[str, Any]]]:
@@ -558,18 +608,35 @@ class BillingServlet:
         if machine is None and not self.config.server.allow_unregistered_serials:
             msg = f"Unrecognised serial {req.keychipid} attempted billing checkin from {request_ip} for {req.gameid} v{req.gamever}."
             await self.data.base.log_event(
-                "allnet", "BILLING_CHECKIN_NG_SERIAL", logging.WARN, msg
+                "allnet", "BILLING_CHECKIN_NG_SERIAL", logging.WARN, msg, ip=request_ip, game=req.gameid, version=req.gamever
             )
             self.logger.warning(msg)
 
             return PlainTextResponse(f"result=1&requestno={req.requestno}&message=Keychip Serial bad\r\n")
         
-        msg = (
+        log_details = {
-            f"Billing checkin from {request_ip}: game {req.gameid} ver {req.gamever} keychip {req.keychipid} playcount "
+            "playcount": req.playcnt,
+            "billing_type": req.billingtype.name,
+            "nearfull": req.nearfull,
+            "playlimit": req.playlimit,
+        }
+        
+        if machine is not None:
+            await self.data.base.log_event("billing", "BILLING_CHECKIN_OK", logging.INFO, "", log_details, None, machine['arcade'], machine['id'], request_ip, req.gameid, req.gamever)
+            
+            self.logger.info(
+                f"Unregistered Billing checkin from {request_ip}: game {req.gameid} ver {req.gamever} keychip {req.keychipid} playcount "
                 f"{req.playcnt} billing_type {req.billingtype.name} nearfull {req.nearfull} playlimit {req.playlimit}"
             )
-        self.logger.info(msg)
+        else:
-        await self.data.base.log_event("billing", "BILLING_CHECKIN_OK", logging.INFO, msg)
+            log_details['serial'] = req.keychipid
+            await self.data.base.log_event("billing", "BILLING_CHECKIN_OK_UNREG", logging.INFO, "", log_details, None, None, None, request_ip, req.gameid, req.gamever)
+        
+            self.logger.info(
+                f"Unregistered Billing checkin from {request_ip}: game {req.gameid} ver {req.gamever} keychip {req.keychipid} playcount "
+                f"{req.playcnt} billing_type {req.billingtype.name} nearfull {req.nearfull} playlimit {req.playlimit}"
+            )
+
         if req.traceleft > 0:
             self.logger.warn(f"{req.traceleft} unsent tracelogs")
         kc_playlimit = req.playlimit

core/data/alembic/versions/2d024cf145a1_add_event_log_game_version.py

@@ -0,0 +1,46 @@
+"""add_event_log_game_version
+
+Revision ID: 2d024cf145a1
+Revises: 2bf9f38d9444
+Create Date: 2024-05-21 23:41:31.445331
+
+"""
+from alembic import op
+import sqlalchemy as sa
+from sqlalchemy.dialects import mysql
+
+# revision identifiers, used by Alembic.
+revision = '2d024cf145a1'
+down_revision = '2bf9f38d9444'
+branch_labels = None
+depends_on = None
+
+
+def upgrade():
+    # ### commands auto generated by Alembic - please adjust! ###
+    op.add_column('event_log', sa.Column('game', sa.TEXT(length=4), nullable=True))
+    op.add_column('event_log', sa.Column('version', sa.TEXT(length=24), nullable=True))
+    op.alter_column('event_log', 'ip',
+               existing_type=mysql.TINYTEXT(),
+               type_=sa.TEXT(length=39),
+               existing_nullable=True)
+    op.alter_column('event_log', 'when_logged',
+               existing_type=mysql.TIMESTAMP(),
+               server_default=sa.text('now()'),
+               existing_nullable=False)
+    # ### end Alembic commands ###
+
+
+def downgrade():
+    # ### commands auto generated by Alembic - please adjust! ###
+    op.alter_column('event_log', 'when_logged',
+               existing_type=mysql.TIMESTAMP(),
+               server_default=sa.text('current_timestamp()'),
+               existing_nullable=False)
+    op.alter_column('event_log', 'ip',
+               existing_type=sa.TEXT(length=39),
+               type_=mysql.TINYTEXT(),
+               existing_nullable=True)
+    op.drop_column('event_log', 'version')
+    op.drop_column('event_log', 'game')
+    # ### end Alembic commands ###

core/data/schema/base.py

@@ -27,6 +27,8 @@ event_log = Table(
     Column("arcade", INTEGER, ForeignKey("arcade.id", ondelete="cascade", onupdate="cascade")),
     Column("machine", INTEGER, ForeignKey("machine.id", ondelete="cascade", onupdate="cascade")),
     Column("ip", TEXT(39)),
+    Column("game", TEXT(4)),
+    Column("version", TEXT(24)),
     Column("message", String(1000), nullable=False),
     Column("details", JSON, nullable=False),
     Column("when_logged", TIMESTAMP, nullable=False, server_default=func.now()),
@@ -80,7 +82,8 @@ class BaseData:
         return randrange(10000, 9999999)
 
     async def log_event(
-        self, system: str, type: str, severity: int, message: str, details: Dict = {}, user: int = None, arcade: int = None, machine: int = None, ip: str = None
+        self, system: str, type: str, severity: int, message: str, details: Dict = {}, user: int = None, 
+        arcade: int = None, machine: int = None, ip: str = None, game: str = None, version: str = None
     ) -> Optional[int]:
         sql = event_log.insert().values(
             system=system,
@@ -90,6 +93,8 @@ class BaseData:
             arcade=arcade,
             machine=machine,
             ip=ip,
+            game=game,
+            version=version,
             message=message,
             details=json.dumps(details),
         )