From 276d49981e94a3456852aa14798ceb4f00b4e3af Mon Sep 17 00:00:00 2001 From: Fabian Dill Date: Tue, 19 Jan 2021 06:37:35 +0100 Subject: [PATCH] Convert WebUI to logging.Handler subclass --- MultiClient.py | 130 +++++++++++++++++++++++++------------------------ NetUtils.py | 1 + WebUI.py | 27 +++------- 3 files changed, 74 insertions(+), 84 deletions(-) diff --git a/MultiClient.py b/MultiClient.py index f93544eb..3f1afc89 100644 --- a/MultiClient.py +++ b/MultiClient.py @@ -35,6 +35,8 @@ import WebUI import Regions import Utils +logger = logging.getLogger("Client") + def create_named_task(coro, *args, name=None): if not name: @@ -52,6 +54,7 @@ class Context(): # WebUI Stuff self.ui_node = WebUI.WebUiClient() + logger.addHandler(self.ui_node) self.custom_address = None self.webui_socket_port: typing.Optional[int] = port self.hint_cost = 0 @@ -118,6 +121,7 @@ class Context(): return await self.server.socket.send(json.dumps(msgs)) + color_codes = {'reset': 0, 'bold': 1, 'underline': 4, 'black': 30, 'red': 31, 'green': 32, 'yellow': 33, 'blue': 34, 'magenta': 35, 'cyan': 36, 'white': 37, 'black_bg': 40, 'red_bg': 41, 'green_bg': 42, 'yellow_bg': 43, 'blue_bg': 44, 'purple_bg': 45, 'cyan_bg': 46, 'white_bg': 47} @@ -422,11 +426,11 @@ def launch_qusb2snes(ctx: Context): qusb2snes_path = Utils.local_path(qusb2snes_path) if os.path.isfile(qusb2snes_path): - ctx.ui_node.log_info(f"Attempting to start {qusb2snes_path}") + logger.info(f"Attempting to start {qusb2snes_path}") import subprocess subprocess.Popen(qusb2snes_path, cwd=os.path.dirname(qusb2snes_path)) else: - ctx.ui_node.log_info( + logger.info( f"Attempt to start (Q)Usb2Snes was aborted as path {qusb2snes_path} was not found, " f"please start it yourself if it is not running") @@ -434,7 +438,7 @@ def launch_qusb2snes(ctx: Context): async def _snes_connect(ctx: Context, address: str): address = f"ws://{address}" if "://" not in address else address - ctx.ui_node.log_info("Connecting to QUsb2snes at %s ..." % address) + logger.info("Connecting to QUsb2snes at %s ..." % address) seen_problems = set() succesful = False while not succesful: @@ -446,7 +450,7 @@ async def _snes_connect(ctx: Context, address: str): # only tell the user about new problems, otherwise silently lay in wait for a working connection if problem not in seen_problems: seen_problems.add(problem) - ctx.ui_node.log_error(f"Error connecting to QUsb2snes ({problem})") + logger.error(f"Error connecting to QUsb2snes ({problem})") if len(seen_problems) == 1: # this is the first problem. Let's try launching QUsb2snes if it isn't already running @@ -469,7 +473,7 @@ async def get_snes_devices(ctx: Context): devices = reply['Results'] if 'Results' in reply and len(reply['Results']) > 0 else None if not devices: - ctx.ui_node.log_info('No SNES device found. Ensure QUsb2Snes is running and connect it to the multibridge.') + logger.info('No SNES device found. Ensure QUsb2Snes is running and connect it to the multibridge.') while not devices: await asyncio.sleep(1) await socket.send(json.dumps(DeviceList_Request)) @@ -484,7 +488,7 @@ async def get_snes_devices(ctx: Context): async def snes_connect(ctx: Context, address): global SNES_RECONNECT_DELAY if ctx.snes_socket is not None and ctx.snes_state == SNES_CONNECTED: - ctx.ui_node.log_error('Already connected to snes') + logger.error('Already connected to snes') return recv_task = None @@ -510,7 +514,7 @@ async def snes_connect(ctx: Context, address): return - ctx.ui_node.log_info("Attaching to " + device) + logger.info("Attaching to " + device) Attach_Request = { "Opcode": "Attach", @@ -523,12 +527,12 @@ async def snes_connect(ctx: Context, address): ctx.ui_node.send_connection_status(ctx) if 'sd2snes' in device.lower() or 'COM' in device: - ctx.ui_node.log_info("SD2SNES/FXPAK Detected") + logger.info("SD2SNES/FXPAK Detected") ctx.is_sd2snes = True await ctx.snes_socket.send(json.dumps({"Opcode" : "Info", "Space" : "SNES"})) reply = json.loads(await ctx.snes_socket.recv()) if reply and 'Results' in reply: - ctx.ui_node.log_info(reply['Results']) + logger.info(reply['Results']) else: ctx.is_sd2snes = False @@ -548,9 +552,9 @@ async def snes_connect(ctx: Context, address): ctx.snes_socket = None ctx.snes_state = SNES_DISCONNECTED if not ctx.snes_reconnect_address: - ctx.ui_node.log_error("Error connecting to snes (%s)" % e) + logger.error("Error connecting to snes (%s)" % e) else: - ctx.ui_node.log_error(f"Error connecting to snes, attempt again in {SNES_RECONNECT_DELAY}s") + logger.error(f"Error connecting to snes, attempt again in {SNES_RECONNECT_DELAY}s") asyncio.create_task(snes_autoreconnect(ctx)) SNES_RECONNECT_DELAY *= 2 @@ -577,11 +581,11 @@ async def snes_recv_loop(ctx: Context): try: async for msg in ctx.snes_socket: ctx.snes_recv_queue.put_nowait(msg) - ctx.ui_node.log_warning("Snes disconnected") + logger.warning("Snes disconnected") except Exception as e: if not isinstance(e, websockets.WebSocketException): - logging.exception(e) - ctx.ui_node.log_error("Lost connection to the snes, type /snes to reconnect") + logger.exception(e) + logger.error("Lost connection to the snes, type /snes to reconnect") finally: socket, ctx.snes_socket = ctx.snes_socket, None if socket is not None and not socket.closed: @@ -595,7 +599,7 @@ async def snes_recv_loop(ctx: Context): ctx.rom = None if ctx.snes_reconnect_address: - ctx.ui_node.log_info(f"...reconnecting in {SNES_RECONNECT_DELAY}s") + logger.info(f"...reconnecting in {SNES_RECONNECT_DELAY}s") asyncio.create_task(snes_autoreconnect(ctx)) @@ -624,10 +628,10 @@ async def snes_read(ctx : Context, address, size): break if len(data) != size: - logging.error('Error reading %s, requested %d bytes, received %d' % (hex(address), size, len(data))) + logger.error('Error reading %s, requested %d bytes, received %d' % (hex(address), size, len(data))) if len(data): - ctx.ui_node.log_error(str(data)) - ctx.ui_node.log_warning('Unable to connect to SNES Device because QUsb2Snes broke temporarily.' + logger.error(str(data)) + logger.warning('Unable to connect to SNES Device because QUsb2Snes broke temporarily.' 'Try un-selecting and re-selecting the SNES Device.') if ctx.snes_socket is not None and not ctx.snes_socket.closed: await ctx.snes_socket.close() @@ -652,7 +656,7 @@ async def snes_write(ctx : Context, write_list): for address, data in write_list: if (address < WRAM_START) or ((address + len(data)) > (WRAM_START + WRAM_SIZE)): - ctx.ui_node.log_error("SD2SNES: Write out of range %s (%d)" % (hex(address), len(data))) + logger.error("SD2SNES: Write out of range %s (%d)" % (hex(address), len(data))) return False for ptr, byte in enumerate(data, address + 0x7E0000 - WRAM_START): cmd += b'\xA9' # LDA @@ -669,7 +673,7 @@ async def snes_write(ctx : Context, write_list): await ctx.snes_socket.send(json.dumps(PutAddress_Request)) await ctx.snes_socket.send(cmd) else: - logging.warning(f"Could not send data to SNES: {cmd}") + logger.warning(f"Could not send data to SNES: {cmd}") except websockets.ConnectionClosed: return False else: @@ -682,7 +686,7 @@ async def snes_write(ctx : Context, write_list): await ctx.snes_socket.send(json.dumps(PutAddress_Request)) await ctx.snes_socket.send(data) else: - logging.warning(f"Could not send data to SNES: {data}") + logger.warning(f"Could not send data to SNES: {data}") except websockets.ConnectionClosed: return False @@ -719,7 +723,7 @@ async def server_loop(ctx: Context, address=None): ctx.ui_node.send_connection_status(ctx) cached_address = None if ctx.server and ctx.server.socket: - ctx.ui_node.log_error('Already connected') + logger.error('Already connected') return if address is None: # set through CLI or BMBP @@ -731,22 +735,22 @@ async def server_loop(ctx: Context, address=None): servers = cached_address = Utils.persistent_load()["servers"] address = servers[rom] if rom and rom in servers else servers["default"] except Exception as e: - logging.debug(f"Could not find cached server address. {e}") + logger.debug(f"Could not find cached server address. {e}") # Wait for the user to provide a multiworld server address if not address: - logging.info('Please connect to a multiworld server.') + logger.info('Please connect to a multiworld server.') ctx.ui_node.poll_for_server_ip() return address = f"ws://{address}" if "://" not in address else address port = urllib.parse.urlparse(address).port or 38281 - ctx.ui_node.log_info('Connecting to multiworld server at %s' % address) + logger.info('Connecting to multiworld server at %s' % address) try: socket = await websockets.connect(address, port=port, ping_timeout=None, ping_interval=None) ctx.server = Endpoint(socket) - ctx.ui_node.log_info('Connected') + logger.info('Connected') ctx.server_address = address ctx.ui_node.send_connection_status(ctx) SERVER_RECONNECT_DELAY = START_RECONNECT_DELAY @@ -754,21 +758,21 @@ async def server_loop(ctx: Context, address=None): for msg in json.loads(data): cmd, args = (msg[0], msg[1]) if len(msg) > 1 else (msg, None) await process_server_cmd(ctx, cmd, args) - ctx.ui_node.log_warning('Disconnected from multiworld server, type /connect to reconnect') + logger.warning('Disconnected from multiworld server, type /connect to reconnect') except WebUI.WaitingForUiException: pass except ConnectionRefusedError: if cached_address: - ctx.ui_node.log_error('Unable to connect to multiworld server at cached address. ' + logger.error('Unable to connect to multiworld server at cached address. ' 'Please use the connect button above.') else: - ctx.ui_node.log_error('Connection refused by the multiworld server') + logger.error('Connection refused by the multiworld server') except (OSError, websockets.InvalidURI): - ctx.ui_node.log_error('Failed to connect to the multiworld server') + logger.error('Failed to connect to the multiworld server') except Exception as e: - ctx.ui_node.log_error('Lost connection to the multiworld server, type /connect to reconnect') + logger.error('Lost connection to the multiworld server, type /connect to reconnect') if not isinstance(e, websockets.WebSocketException): - logging.exception(e) + logger.exception(e) finally: ctx.awaiting_rom = False ctx.auth = None @@ -780,7 +784,7 @@ async def server_loop(ctx: Context, address=None): ctx.server = None ctx.server_task = None if ctx.server_address: - ctx.ui_node.log_info(f"... reconnecting in {SERVER_RECONNECT_DELAY}s") + logger.info(f"... reconnecting in {SERVER_RECONNECT_DELAY}s") ctx.ui_node.send_connection_status(ctx) asyncio.create_task(server_autoreconnect(ctx)) SERVER_RECONNECT_DELAY *= 2 @@ -797,20 +801,20 @@ async def server_autoreconnect(ctx: Context): async def process_server_cmd(ctx: Context, cmd, args): if cmd == 'RoomInfo': - ctx.ui_node.log_info('--------------------------------') - ctx.ui_node.log_info('Room Information:') - ctx.ui_node.log_info('--------------------------------') + logger.info('--------------------------------') + logger.info('Room Information:') + logger.info('--------------------------------') version = args.get("version", "unknown Bonta Protocol") if isinstance(version, list): ctx.server_version = tuple(version) version = ".".join(str(item) for item in version) else: ctx.server_version = (0, 0, 0) - ctx.ui_node.log_info(f'Server protocol version: {version}') + logger.info(f'Server protocol version: {version}') if "tags" in args: - ctx.ui_node.log_info("Server protocol tags: " + ", ".join(args["tags"])) + logger.info("Server protocol tags: " + ", ".join(args["tags"])) if args['password']: - ctx.ui_node.log_info('Password required') + logger.info('Password required') if "forfeit_mode" in args: # could also be version > 2.2.1, but going with implicit content here logging.info(f"Forfeit setting: {args['forfeit_mode']}") logging.info(f"Remaining setting: {args['remaining_mode']}") @@ -822,16 +826,16 @@ async def process_server_cmd(ctx: Context, cmd, args): ctx.remaining_mode = args['remaining_mode'] ctx.ui_node.send_game_info(ctx) if len(args['players']) < 1: - ctx.ui_node.log_info('No player connected') + logger.info('No player connected') else: args['players'].sort() current_team = -1 - ctx.ui_node.log_info('Connected players:') + logger.info('Connected players:') for team, slot, name in args['players']: if team != current_team: - ctx.ui_node.log_info(f' Team #{team + 1}') + logger.info(f' Team #{team + 1}') current_team = team - ctx.ui_node.log_info(' %s (Player %d)' % (name, slot)) + logger.info(' %s (Player %d)' % (name, slot)) await server_auth(ctx, args['password']) elif cmd == 'ConnectionRefused': @@ -848,7 +852,7 @@ async def process_server_cmd(ctx: Context, cmd, args): raise Exception('Server reported your client version as incompatible') #last to check, recoverable problem elif 'InvalidPassword' in args: - ctx.ui_node.log_error('Invalid password') + logger.error('Invalid password') ctx.password = None await server_auth(ctx, True) else: @@ -858,7 +862,7 @@ async def process_server_cmd(ctx: Context, cmd, args): elif cmd == 'Connected': if ctx.send_unsafe: ctx.send_unsafe = False - ctx.ui_node.log_info(f'Turning off sending of ALL location checks not declared as missing. If you want it on, please use /send_unsafe true') + logger.info(f'Turning off sending of ALL location checks not declared as missing. If you want it on, please use /send_unsafe true') Utils.persistent_store("servers", "default", ctx.server_address) Utils.persistent_store("servers", ctx.rom, ctx.server_address) ctx.team, ctx.slot = args[0] @@ -898,7 +902,7 @@ async def process_server_cmd(ctx: Context, cmd, args): if location not in ctx.locations_info: replacements = {0xA2: 'Small Key', 0x9D: 'Big Key', 0x8D: 'Compass', 0x7D: 'Map'} item_name = replacements.get(item, get_item_name_from_id(item)) - ctx.ui_node.log_info( + logger.info( f"Saw {color(item_name, 'red', 'bold')} at {list(Regions.location_table.keys())[location - 1]}") ctx.locations_info[location] = (item, player) ctx.watcher_event.set() @@ -929,8 +933,8 @@ async def process_server_cmd(ctx: Context, cmd, args): locations = json.loads(args['locations']) if ctx.items_missing: for location in locations: - ctx.ui_node.log_info(f'Missing: {location}') - ctx.ui_node.log_info(f'Found {len(locations)} missing location checks') + logger.info(f'Missing: {location}') + logger.info(f'Found {len(locations)} missing location checks') ctx.items_missing = [location for location in locations] elif cmd == 'Hint': @@ -957,13 +961,13 @@ async def process_server_cmd(ctx: Context, cmd, args): ctx.player_names = {p: n for p, n in args} elif cmd == 'Print': - ctx.ui_node.log_info(args) + logger.info(args) elif cmd == 'HintPointUpdate': ctx.hint_points = args[0] else: - logging.debug(f"unknown command {args}") + logger.debug(f"unknown command {args}") def get_tags(ctx: Context): @@ -975,11 +979,11 @@ def get_tags(ctx: Context): async def server_auth(ctx: Context, password_requested): if password_requested and not ctx.password: - ctx.ui_node.log_info('Enter the password required to join this game:') + logger.info('Enter the password required to join this game:') ctx.password = await console_input(ctx) if ctx.rom is None: ctx.awaiting_rom = True - ctx.ui_node.log_info( + logger.info( 'No ROM detected, awaiting snes connection to authenticate to the multiworld server (/snes)') return ctx.awaiting_rom = False @@ -1009,7 +1013,7 @@ class ClientCommandProcessor(CommandProcessor): self.ctx = ctx def output(self, text: str): - self.ctx.ui_node.log_info(text) + logger.info(text) def _cmd_exit(self) -> bool: """Close connections and client""" @@ -1046,7 +1050,7 @@ class ClientCommandProcessor(CommandProcessor): def _cmd_received(self) -> bool: """List all received items""" - self.ctx.ui_node.log_info('Received items:') + logger.info('Received items:') for index, item in enumerate(self.ctx.items_received, 1): self.ctx.ui_node.notify_item_received(self.ctx.player_names[item.player], get_item_name_from_id(item.item), get_location_name_from_address(item.location), index, @@ -1098,7 +1102,7 @@ class ClientCommandProcessor(CommandProcessor): self.ctx.found_items = toggle.lower() in {"1", "true", "on"} else: self.ctx.found_items = not self.ctx.found_items - self.ctx.ui_node.log_info(f"Set showing team items to {self.ctx.found_items}") + logger.info(f"Set showing team items to {self.ctx.found_items}") asyncio.create_task(self.ctx.send_msgs([['UpdateTags', get_tags(self.ctx)]])) return True @@ -1109,7 +1113,7 @@ class ClientCommandProcessor(CommandProcessor): else: self.ctx.slow_mode = not self.ctx.slow_mode - self.ctx.ui_node.log_info(f"Setting slow mode to {self.ctx.slow_mode}") + logger.info(f"Setting slow mode to {self.ctx.slow_mode}") def _cmd_web(self): if self.ctx.webui_socket_port: @@ -1121,9 +1125,9 @@ class ClientCommandProcessor(CommandProcessor): """Force sending of locations the server did not specify was actually missing. WARNING: This may brick online trackers. Turned off on reconnect.""" if toggle: self.ctx.send_unsafe = toggle.lower() in {"1", "true", "on"} - self.ctx.ui_node.log_info(f'Turning {("on" if self.ctx.send_unsafe else "off")} the option to send ALL location checks to the multiserver.') + logger.info(f'Turning {("on" if self.ctx.send_unsafe else "off")} the option to send ALL location checks to the multiserver.') else: - self.ctx.ui_node.log_info("You must specify /send_unsafe true explicitly.") + logger.info("You must specify /send_unsafe true explicitly.") self.ctx.send_unsafe = False def default(self, raw: str): @@ -1156,7 +1160,7 @@ async def track_locations(ctx : Context, roomid, roomdata): def new_check(location): ctx.unsafe_locations_checked.add(location) - ctx.ui_node.log_info("New check: %s (%d/216)" % (location, len(ctx.unsafe_locations_checked))) + logger.info("New check: %s (%d/216)" % (location, len(ctx.unsafe_locations_checked))) ctx.ui_node.send_location_check(ctx, location) for location, (loc_roomid, loc_mask) in location_table_uw.items(): @@ -1164,7 +1168,7 @@ async def track_locations(ctx : Context, roomid, roomdata): if location not in ctx.unsafe_locations_checked and loc_roomid == roomid and (roomdata << 4) & loc_mask != 0: new_check(location) except Exception as e: - ctx.ui_node.log_info(f"Exception: {e}") + logger.info(f"Exception: {e}") uw_begin = 0x129 uw_end = 0 @@ -1227,7 +1231,7 @@ async def send_finished_game(ctx: Context): await ctx.send_msgs([['GameFinished', '']]) ctx.finished_game = True except Exception as ex: - logging.exception(ex) + logger.exception(ex) async def game_watcher(ctx : Context): @@ -1257,7 +1261,7 @@ async def game_watcher(ctx : Context): await server_auth(ctx, False) if ctx.auth and ctx.auth != ctx.rom: - ctx.ui_node.log_warning("ROM change detected, please reconnect to the multiworld server") + logger.warning("ROM change detected, please reconnect to the multiworld server") await ctx.disconnect() gamemode = await snes_read(ctx, WRAM_START + 0x10, 1) @@ -1321,7 +1325,7 @@ async def game_watcher(ctx : Context): if scout_location > 0 and scout_location not in ctx.locations_scouted: ctx.locations_scouted.add(scout_location) - ctx.ui_node.log_info(f'Scouting item at {list(Regions.location_table.keys())[scout_location - 1]}') + logger.info(f'Scouting item at {list(Regions.location_table.keys())[scout_location - 1]}') await ctx.send_msgs([['LocationScouts', [scout_location]]]) await track_locations(ctx, roomid, roomdata) diff --git a/NetUtils.py b/NetUtils.py index d99b2086..1dbc072a 100644 --- a/NetUtils.py +++ b/NetUtils.py @@ -12,6 +12,7 @@ class Node: def __init__(self): self.endpoints = [] + super(Node, self).__init__() def broadcast_all(self, msgs): msgs = json.dumps(msgs) diff --git a/WebUI.py b/WebUI.py index 015c7118..cad9694f 100644 --- a/WebUI.py +++ b/WebUI.py @@ -1,6 +1,6 @@ import http.server import logging -import os +import typing import socket import socketserver import threading @@ -12,33 +12,18 @@ from NetUtils import Node from MultiClient import Context import Utils -logger = logging.getLogger("WebUIRelay") - -class WebUiClient(Node): +class WebUiClient(Node, logging.Handler): def __init__(self): - super().__init__() + super(WebUiClient, self).__init__() self.manual_snes = None @staticmethod - def build_message(msg_type: str, content: dict) -> dict: + def build_message(msg_type: str, content: typing.Union[str, dict]) -> dict: return {'type': msg_type, 'content': content} - def log_info(self, message, *args, **kwargs): - self.broadcast_all(self.build_message('info', message)) - logger.info(message, *args, **kwargs) - - def log_warning(self, message, *args, **kwargs): - self.broadcast_all(self.build_message('warning', message)) - logger.warning(message, *args, **kwargs) - - def log_error(self, message, *args, **kwargs): - self.broadcast_all(self.build_message('error', message)) - logger.error(message, *args, **kwargs) - - def log_critical(self, message, *args, **kwargs): - self.broadcast_all(self.build_message('critical', message)) - logger.critical(message, *args, **kwargs) + def emit(self, record: logging.LogRecord) -> None: + self.broadcast_all({"type": record.levelname.lower(), "content": str(record.msg)}) def send_chat_message(self, message): self.broadcast_all(self.build_message('chat', message))