Convert WebUI to logging.Handler subclass

This commit is contained in:
Fabian Dill 2021-01-19 06:37:35 +01:00
parent e2075686c2
commit 276d49981e
3 changed files with 74 additions and 84 deletions

View File

@ -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)

View File

@ -12,6 +12,7 @@ class Node:
def __init__(self):
self.endpoints = []
super(Node, self).__init__()
def broadcast_all(self, msgs):
msgs = json.dumps(msgs)

View File

@ -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))