From 4ee4c26f5e5161dc789eaac3379bba610182f1ee Mon Sep 17 00:00:00 2001 From: Kevin Trocolli Date: Wed, 22 May 2024 00:05:32 -0400 Subject: [PATCH] allnet: enhance logging --- core/allnet.py | 113 ++++++++++++++---- ...2d024cf145a1_add_event_log_game_version.py | 46 +++++++ core/data/schema/base.py | 7 +- 3 files changed, 142 insertions(+), 24 deletions(-) create mode 100644 core/data/alembic/versions/2d024cf145a1_add_event_log_game_version.py diff --git a/core/allnet.py b/core/allnet.py index b03d168..861a603 100644 --- a/core/allnet.py +++ b/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,7 +204,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['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") - 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) + 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, {}, 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}") - 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}") + if resp.uri: + 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") - await self.data.base.log_event("allnet", "DLORDER_INI_SENT", logging.INFO, f"{Utils.get_ip_addr(request)} successfully recieved {req_file}") + 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"{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") + + log_details = { + "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}" + ) + else: + 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}" + ) - msg = ( - f"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) - await self.data.base.log_event("billing", "BILLING_CHECKIN_OK", logging.INFO, msg) if req.traceleft > 0: self.logger.warn(f"{req.traceleft} unsent tracelogs") kc_playlimit = req.playlimit diff --git a/core/data/alembic/versions/2d024cf145a1_add_event_log_game_version.py b/core/data/alembic/versions/2d024cf145a1_add_event_log_game_version.py new file mode 100644 index 0000000..b947763 --- /dev/null +++ b/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 ### diff --git a/core/data/schema/base.py b/core/data/schema/base.py index a87ce00..a6fd68d 100644 --- a/core/data/schema/base.py +++ b/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), )