proper logs

This commit is contained in:
Devaev Maxim 2020-06-05 06:27:23 +03:00
parent 1eb440b060
commit 83a8eb8dd2
4 changed files with 27 additions and 27 deletions

View File

@ -88,8 +88,8 @@ class IpmiServer(BaseIpmiServer): # pylint: disable=too-many-instance-attribute
except (aiohttp.ClientError, asyncio.TimeoutError): except (aiohttp.ClientError, asyncio.TimeoutError):
session.send_ipmi_response(code=0xFF) session.send_ipmi_response(code=0xFF)
except Exception: except Exception:
get_logger(0).exception("Unexpected exception while handling IPMI request: netfn=%d; command=%d", get_logger(0).exception("[%s]: Unexpected exception while handling IPMI request: netfn=%d; command=%d",
request["netfn"], request["command"]) session.sockaddr[0], request["netfn"], request["command"])
session.send_ipmi_response(code=0xFF) session.send_ipmi_response(code=0xFF)
else: else:
session.send_ipmi_response(code=0xC1) session.send_ipmi_response(code=0xC1)
@ -121,14 +121,14 @@ class IpmiServer(BaseIpmiServer): # pylint: disable=too-many-instance-attribute
async def runner(): # type: ignore async def runner(): # type: ignore
logger = get_logger(0) logger = get_logger(0)
credentials = self.__auth_manager.get_credentials(session.username.decode()) credentials = self.__auth_manager.get_credentials(session.username.decode())
logger.info("Client %s: Performing request %s from user %r (IPMI) as %r (KVMD)", logger.info("[%s]: Performing request %s from user %r (IPMI) as %r (KVMD)",
session.sockaddr[0], name, credentials.ipmi_user, credentials.kvmd_user) session.sockaddr[0], name, credentials.ipmi_user, credentials.kvmd_user)
try: try:
async with self.__kvmd.make_session(credentials.kvmd_user, credentials.kvmd_passwd) as kvmd_session: async with self.__kvmd.make_session(credentials.kvmd_user, credentials.kvmd_passwd) as kvmd_session:
method = functools.reduce(getattr, method_path.split("."), kvmd_session) method = functools.reduce(getattr, method_path.split("."), kvmd_session)
return (await method(**kwargs)) return (await method(**kwargs))
except (aiohttp.ClientError, asyncio.TimeoutError) as err: except (aiohttp.ClientError, asyncio.TimeoutError) as err:
logger.error("Can't perform request %s: %s", name, err) logger.error("[%s]: Can't perform request %s: %s", session.sockaddr[0], name, err)
raise raise
return aiotools.run_sync(runner()) return aiotools.run_sync(runner())

View File

@ -79,11 +79,11 @@ class RfbClient(RfbClientStream): # pylint: disable=too-many-instance-attribute
self.__rfb_version = 0 self.__rfb_version = 0
self._encodings = RfbClientEncodings(frozenset()) self._encodings = RfbClientEncodings(frozenset())
get_logger(0).info("Connected client: %s", self._remote)
# ===== # =====
async def _run(self, **coros: Coroutine) -> None: async def _run(self, **coros: Coroutine) -> None:
logger = get_logger(0)
logger.info("[entry] [%s]: Starting client tasks ...", self._remote)
tasks = list(map(asyncio.create_task, [ tasks = list(map(asyncio.create_task, [
self.__wrapper(name, coro) self.__wrapper(name, coro)
for (name, coro) in {"main": self.__main_task_loop(), **coros}.items() for (name, coro) in {"main": self.__main_task_loop(), **coros}.items()
@ -95,7 +95,7 @@ class RfbClient(RfbClientStream): # pylint: disable=too-many-instance-attribute
task.cancel() task.cancel()
await asyncio.gather(*tasks, return_exceptions=True) await asyncio.gather(*tasks, return_exceptions=True)
await self._close() await self._close()
get_logger(0).info("Connection closed: %s", self._remote) logger.info("[entry] [%s]: Connection closed", self._remote)
async def __wrapper(self, name: str, coro: Coroutine) -> None: async def __wrapper(self, name: str, coro: Coroutine) -> None:
logger = get_logger(0) logger = get_logger(0)
@ -103,14 +103,14 @@ class RfbClient(RfbClientStream): # pylint: disable=too-many-instance-attribute
await coro await coro
raise RuntimeError("Subtask just finished without any exception") raise RuntimeError("Subtask just finished without any exception")
except asyncio.CancelledError: except asyncio.CancelledError:
logger.info("[%s] Client %s: Cancelling subtask ...", name, self._remote) logger.info("[%s] [%s]: Cancelling subtask ...", name, self._remote)
raise raise
except RfbConnectionError as err: except RfbConnectionError as err:
logger.info("[%s] Client %s: Gone: %s", name, self._remote, err) logger.info("[%s] [%s]: Gone: %s", name, self._remote, err)
except (RfbError, ssl.SSLError) as err: except (RfbError, ssl.SSLError) as err:
logger.error("[%s] Client %s: Error: %s", name, self._remote, err) logger.error("[%s] [%s]: Error: %s", name, self._remote, err)
except Exception: except Exception:
logger.exception("[%s] Unhandled exception with client %s", name, self._remote) logger.exception("[%s] [%s]: Unhandled exception", name, self._remote)
async def __main_task_loop(self) -> None: async def __main_task_loop(self) -> None:
await self.__handshake_version() await self.__handshake_version()
@ -200,7 +200,7 @@ class RfbClient(RfbClientStream): # pylint: disable=too-many-instance-attribute
except ValueError: except ValueError:
raise RfbError(f"Invalid version response: {response!r}") raise RfbError(f"Invalid version response: {response!r}")
self.__rfb_version = (3 if version == 5 else version) self.__rfb_version = (3 if version == 5 else version)
get_logger(0).info("[main] Client %s: Using RFB version 3.%d", self._remote, self.__rfb_version) get_logger(0).info("[main] [%s]: Using RFB version 3.%d", self._remote, self.__rfb_version)
# ===== # =====
@ -225,7 +225,7 @@ class RfbClient(RfbClientStream): # pylint: disable=too-many-instance-attribute
raise RfbError(f"Invalid security type: {sec_type}") raise RfbError(f"Invalid security type: {sec_type}")
(sec_name, handler) = sec_types[sec_type] (sec_name, handler) = sec_types[sec_type]
get_logger(0).info("[main] Client %s: Using %s security type", self._remote, sec_name) get_logger(0).info("[main] [%s]: Using %s security type", self._remote, sec_name)
await handler() await handler()
async def __handshake_security_vencrypt(self) -> None: async def __handshake_security_vencrypt(self) -> None:
@ -265,7 +265,7 @@ class RfbClient(RfbClientStream): # pylint: disable=too-many-instance-attribute
raise RfbError(f"Invalid VeNCrypt auth type: {auth_type}") raise RfbError(f"Invalid VeNCrypt auth type: {auth_type}")
(auth_name, tls, handler) = auth_types[auth_type] (auth_name, tls, handler) = auth_types[auth_type]
get_logger(0).info("[main] Client %s: Using %s auth type", self._remote, auth_name) get_logger(0).info("[main] [%s]: Using %s auth type", self._remote, auth_name)
if tls: if tls:
await self._write_struct("B", 1) # Ack await self._write_struct("B", 1) # Ack
@ -322,7 +322,7 @@ class RfbClient(RfbClientStream): # pylint: disable=too-many-instance-attribute
async def __handshake_security_send_result(self, allow: bool, allow_msg: str, deny_msg: str, deny_reason: str) -> None: async def __handshake_security_send_result(self, allow: bool, allow_msg: str, deny_msg: str, deny_reason: str) -> None:
if allow: if allow:
get_logger(0).info("[main] Client %s: %s", self._remote, allow_msg) get_logger(0).info("[main] [%s]: %s", self._remote, allow_msg)
await self._write_struct("L", 0) await self._write_struct("L", 0)
else: else:
await self._write_struct("L", 1, drain=(self.__rfb_version < 8)) await self._write_struct("L", 1, drain=(self.__rfb_version < 8))
@ -381,7 +381,7 @@ class RfbClient(RfbClientStream): # pylint: disable=too-many-instance-attribute
if encodings_count > 1024: if encodings_count > 1024:
raise RfbError(f"Too many encodings: {encodings_count}") raise RfbError(f"Too many encodings: {encodings_count}")
self._encodings = RfbClientEncodings(frozenset(await self._read_struct("l" * encodings_count))) self._encodings = RfbClientEncodings(frozenset(await self._read_struct("l" * encodings_count)))
get_logger(0).info("[main] Client %s: Features: resize=%d; rename=%d; leds=%d", get_logger(0).info("[main] [%s]: Features: resize=%d; rename=%d; leds=%d",
self._remote, self._encodings.has_resize, self._encodings.has_rename, self._encodings.has_leds_state) self._remote, self._encodings.has_resize, self._encodings.has_rename, self._encodings.has_leds_state)
self.__check_tight_jpeg() self.__check_tight_jpeg()
await self._on_set_encodings() await self._on_set_encodings()

View File

@ -32,7 +32,7 @@ from .errors import RfbConnectionError
# ===== # =====
def rfb_format_remote(writer: asyncio.StreamWriter) -> str: def rfb_format_remote(writer: asyncio.StreamWriter) -> str:
return "[%s]:%d" % (writer.transport.get_extra_info("peername")[:2]) return str(writer.transport.get_extra_info("peername")[0])
async def rfb_close_writer(writer: asyncio.StreamWriter) -> bool: async def rfb_close_writer(writer: asyncio.StreamWriter) -> bool:

View File

@ -140,7 +140,7 @@ class _Client(RfbClient): # pylint: disable=too-many-instance-attributes
assert self.__kvmd_session assert self.__kvmd_session
try: try:
async with self.__kvmd_session.ws() as self.__kvmd_ws: async with self.__kvmd_session.ws() as self.__kvmd_ws:
logger.info("[kvmd] Client %s: Connected to KVMD websocket", self._remote) logger.info("[kvmd] [%s]: Connected to KVMD websocket", self._remote)
self.__ws_connected.set_result(None) self.__ws_connected.set_result(None)
async for event in self.__kvmd_ws.communicate(): async for event in self.__kvmd_ws.communicate():
await self.__process_ws_event(event) await self.__process_ws_event(event)
@ -177,14 +177,14 @@ class _Client(RfbClient): # pylint: disable=too-many-instance-attributes
streaming = False streaming = False
async for (online, width, height, jpeg) in self.__streamer.read_stream(): async for (online, width, height, jpeg) in self.__streamer.read_stream():
if not streaming: if not streaming:
logger.info("[streamer] Client %s: Streaming ...", self._remote) logger.info("[streamer] [%s]: Streaming ...", self._remote)
streaming = True streaming = True
if online: if online:
await self.__send_fb_real(width, height, jpeg) await self.__send_fb_real(width, height, jpeg)
else: else:
await self.__send_fb_stub("No signal") await self.__send_fb_stub("No signal")
except StreamerError as err: except StreamerError as err:
logger.info("[streamer] Client %s: Waiting for stream: %s", self._remote, err) logger.info("[streamer] [%s]: Waiting for stream: %s", self._remote, err)
await self.__send_fb_stub("Waiting for stream ...") await self.__send_fb_stub("Waiting for stream ...")
await asyncio.sleep(1) await asyncio.sleep(1)
@ -260,7 +260,7 @@ class _Client(RfbClient): # pylint: disable=too-many-instance-attributes
assert self.__authorized.done() assert self.__authorized.done()
assert self.__kvmd_session assert self.__kvmd_session
logger = get_logger(0) logger = get_logger(0)
logger.info("[main] Client %s: Printing %d characters ...", self._remote, len(text)) logger.info("[main] [%s]: Printing %d characters ...", self._remote, len(text))
try: try:
(default, available) = await self.__kvmd_session.hid.get_keymaps() (default, available) = await self.__kvmd_session.hid.get_keymaps()
await self.__kvmd_session.hid.print( await self.__kvmd_session.hid.print(
@ -269,12 +269,12 @@ class _Client(RfbClient): # pylint: disable=too-many-instance-attributes
keymap_name=(self.__keymap_name if self.__keymap_name in available else default), keymap_name=(self.__keymap_name if self.__keymap_name in available else default),
) )
except Exception: except Exception:
logger.exception("[main] Client %s: Can't print characters", self._remote) logger.exception("[main] [%s]: Can't print characters", self._remote)
async def _on_set_encodings(self) -> None: async def _on_set_encodings(self) -> None:
assert self.__authorized.done() assert self.__authorized.done()
assert self.__kvmd_session assert self.__kvmd_session
get_logger(0).info("[main] Client %s: Applying streamer params: quality=%d%%; desired_fps=%d ...", get_logger(0).info("[main] [%s]: Applying streamer params: quality=%d%%; desired_fps=%d ...",
self._remote, self._encodings.tight_jpeg_quality, self.__desired_fps) self._remote, self._encodings.tight_jpeg_quality, self.__desired_fps)
await self.__kvmd_session.streamer.set_params(self._encodings.tight_jpeg_quality, self.__desired_fps) await self.__kvmd_session.streamer.set_params(self._encodings.tight_jpeg_quality, self.__desired_fps)
@ -316,13 +316,13 @@ class VncServer: # pylint: disable=too-many-instance-attributes
async def handle_client(reader: asyncio.StreamReader, writer: asyncio.StreamWriter) -> None: async def handle_client(reader: asyncio.StreamReader, writer: asyncio.StreamWriter) -> None:
logger = get_logger(0) logger = get_logger(0)
remote = rfb_format_remote(writer) remote = rfb_format_remote(writer)
logger.info("Preparing client %s ...", remote) logger.info("[entry] [%s]: Connected client", remote)
try: try:
try: try:
async with kvmd.make_session("", "") as kvmd_session: async with kvmd.make_session("", "") as kvmd_session:
none_auth_only = await kvmd_session.auth.check() none_auth_only = await kvmd_session.auth.check()
except (aiohttp.ClientError, asyncio.TimeoutError) as err: except (aiohttp.ClientError, asyncio.TimeoutError) as err:
logger.error("Client %s: Can't check KVMD auth mode: %s: %s", remote, type(err).__name__, err) logger.error("[entry] [%s]: Can't check KVMD auth mode: %s: %s", remote, type(err).__name__, err)
return return
await _Client( await _Client(
@ -340,10 +340,10 @@ class VncServer: # pylint: disable=too-many-instance-attributes
shared_params=shared_params, shared_params=shared_params,
).run() ).run()
except Exception: except Exception:
logger.exception("Client %s: Unhandled exception in client task", remote) logger.exception("[entry] [%s]: Unhandled exception in client task", remote)
finally: finally:
if (await rfb_close_writer(writer)): if (await rfb_close_writer(writer)):
logger.info("Connection is closed in an emergency: %s", remote) logger.info("[entry] [%s]: Connection is closed in an emergency", remote)
self.__handle_client = handle_client self.__handle_client = handle_client