From 06cc2cb5a40e5115c2febb044da47d5a4106ded9 Mon Sep 17 00:00:00 2001 From: Jesse S Date: Tue, 26 Apr 2022 14:21:16 -0700 Subject: [PATCH] 2.7.3 bugfix (#51) * fix: Add debug mode for troubleshooting * fix: use correct delimiter when splitting services list --- asadm.py | 8 ++- lib/live_cluster/client/assocket.py | 9 ++- lib/live_cluster/client/cluster.py | 28 +++++---- lib/live_cluster/client/info.py | 19 +++++- lib/live_cluster/client/node.py | 39 ++++++------ lib/utils/conf.py | 1 + lib/utils/logger.py | 59 +++++++++++++++---- test/unit/live_cluster/client/test_cluster.py | 8 +-- 8 files changed, 117 insertions(+), 54 deletions(-) diff --git a/asadm.py b/asadm.py index 91ae6e8f..e18708f7 100755 --- a/asadm.py +++ b/asadm.py @@ -17,6 +17,7 @@ import inspect import cmd import getpass +import logging import os import re @@ -62,7 +63,7 @@ # codec is registered well before it is used in getaddrinfo. # see https://bugs.python.org/issue29288, https://github.com/aws/aws-cli/blob/1.16.277/awscli/clidriver.py#L55, # and https://github.com/pyinstaller/pyinstaller/issues/1113 for more info :) -u"".encode("idna") +"".encode("idna") __version__ = "$$__version__$$" CMD_FILE_SINGLE_LINE_COMMENT_START = "//" @@ -208,7 +209,7 @@ async def __init__( except Exception as e: await self.do_exit("") - logger.critical(str(e)) + logger.critical(e) if not execute_only_mode: @@ -627,6 +628,9 @@ async def main(): admin_version = get_version() + if cli_args.debug: + logger.setLevel(logging.DEBUG) + if cli_args.help: conf.print_config_help() sys.exit(0) diff --git a/lib/live_cluster/client/assocket.py b/lib/live_cluster/client/assocket.py index 06bf1ad6..72fa48e7 100644 --- a/lib/live_cluster/client/assocket.py +++ b/lib/live_cluster/client/assocket.py @@ -12,6 +12,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +import logging import socket import warnings import asyncio @@ -53,6 +54,8 @@ class ASSocket: + logger = logging.getLogger("asadm") + def __init__( self, ip, port, tls_name, user, password, auth_mode, ssl_context, timeout=5 ): @@ -171,7 +174,8 @@ async def connect(self): if not self.sock: return False self.reader, self.writer = await asyncio.open_connection(sock=self.sock) - except Exception: + except Exception as e: + self.logger.debug(e, include_traceback=True) return False return True @@ -185,7 +189,8 @@ async def is_connected(self): if result is None or result == -1: return False - except Exception: + except Exception as e: + self.logger.debug(e, include_traceback=True) return False return True diff --git a/lib/live_cluster/client/cluster.py b/lib/live_cluster/client/cluster.py index 0353862e..e698a495 100644 --- a/lib/live_cluster/client/cluster.py +++ b/lib/live_cluster/client/cluster.py @@ -24,12 +24,11 @@ from lib.utils.async_object import AsyncObject from lib.utils.lookup_dict import LookupDict -from lib.utils import logger_debug, util, constants +from lib.utils import util, constants from . import client_util from .node import Node -logger = logger_debug.get_debug_logger(__name__, logging.CRITICAL) # interval time in second for cluster refreshing CLUSTER_REFRESH_INTERVAL = 3 @@ -233,8 +232,8 @@ async def get_down_nodes(self): _key = Node.create_key(n[0], n[1]) if _key not in cluster_down_nodes: cluster_down_nodes.append(_key) - except Exception: - pass + except Exception as e: + self.logger.debug(e, include_traceback=True) return cluster_down_nodes @@ -256,8 +255,8 @@ def update_aliases(self, aliases, endpoints, key): node = self.nodes[aliases_node_key] if not node.alive: aliases[node_key] = key - except Exception: - pass + except Exception as e: + self.logger.debug(e, include_traceback=True) async def find_new_nodes(self): added_endpoints = [] @@ -299,7 +298,7 @@ async def _crawl(self): """ nodes_to_add = await self.find_new_nodes() - logger.debug("Nodes to add to cluster: %s", nodes_to_add) + self.logger.debug("Unvisited nodes: %s", nodes_to_add) if not nodes_to_add or len(nodes_to_add) == 0: return @@ -310,7 +309,9 @@ async def _crawl(self): while unvisited - visited: l_unvisited = list(unvisited) - logger.debug("Register nodes in cluster: %s", l_unvisited) + self.logger.debug( + "Attempting to add nodes to the cluster: %s", l_unvisited + ) nodes = await client_util.concurrent_map( self._register_node, l_unvisited ) @@ -348,11 +349,12 @@ async def _crawl(self): all_services.add((node.ip, node.port, node.tls_name)) unvisited = all_services - visited - logger.debug("Peers to add to cluster: %s", unvisited) + self.logger.debug("Peers to add to cluster: %s", unvisited) self._refresh_node_liveliness() - except Exception: - pass + except Exception as e: + self.logger.debug(e, include_traceback=True) + finally: self.clear_node_list() @@ -538,8 +540,8 @@ async def _create_node(self, addr_port_tls, force=False): return new_node except (ASInfoNotAuthenticatedError, ASProtocolError) as e: self.logger.error(e) - except Exception: - pass + except Exception as e: + self.logger.debug(e, include_traceback=True) return None @staticmethod diff --git a/lib/live_cluster/client/info.py b/lib/live_cluster/client/info.py index 6af005bc..518b9fac 100644 --- a/lib/live_cluster/client/info.py +++ b/lib/live_cluster/client/info.py @@ -42,8 +42,7 @@ # fatal when authentication is required. hasbcrypt = False -logger = logging.getLogger(__name__) -logger.setLevel(logging.CRITICAL) +logger = logging.getLogger("asadm") # There are three different headers referenced here in the code. I am adding @@ -1320,6 +1319,13 @@ async def info(reader, writer, names=None): if name != names: if "not authenticated" in name.lower(): return ASInfoNotAuthenticatedError("Connection failed", name) + else: + logger.debug( + "Unexpected key %s in info response %s. Expected key: %s", + name, + lines, + names, + ) return value else: @@ -1331,6 +1337,15 @@ async def info(reader, writer, names=None): # this accounts for the trailing '\n' - cheaper than chomp continue name, sep, value = line.partition("\t") + + if name not in names: + logger.debug( + "Unexpected key %s in info response %s. Exceptable keys: %s", + name, + line, + names, + ) + rdict[name] = value return rdict diff --git a/lib/live_cluster/client/node.py b/lib/live_cluster/client/node.py index bc624587..ecfb4456 100644 --- a/lib/live_cluster/client/node.py +++ b/lib/live_cluster/client/node.py @@ -346,7 +346,7 @@ async def connect(self, address, port): except (ASInfoNotAuthenticatedError, ASProtocolError): raise except Exception as e: - + self.logger.debug(e, include_traceback=True) # Node is offline... fake a node self.ip = address self.fqdn = address @@ -399,14 +399,14 @@ async def login(self): try: if not await sock.login(): - logger.debug( + self.logger.debug( "%s:%s failed to login to socket %s", self.ip, self.port, sock ) await sock.close() return False except ASProtocolError as e: if e.as_response == ASResponse.SECURITY_NOT_ENABLED: - logger.debug( + self.logger.debug( "%s:%s failed to login to socket, security not enabled, ignoring... %s", self.ip, self.port, @@ -416,7 +416,7 @@ async def login(self): self.logger.warning(e) Node.security_disabled_warning = True else: - logger.debug( + self.logger.debug( "%s:%s failed to login to socket %s, exc: %s", self.ip, self.port, @@ -429,7 +429,9 @@ async def login(self): self.socket_pool[self.port].add(sock) self.session_token, self.session_expiration = sock.get_session_info() self.perform_login = False - logger.debug("%s:%s successful login to socket %s", self.ip, self.port, sock) + self.logger.debug( + "%s:%s successful login to socket %s", self.ip, self.port, sock + ) return True @property @@ -528,7 +530,8 @@ async def _get_connection(self, ip, port) -> ASSocket: await sock.close() sock = None - except Exception: + except Exception as e: + self.logger.debug(e, include_traceback=True) pass if sock: @@ -545,15 +548,15 @@ async def _get_connection(self, ip, port) -> ASSocket: timeout=self._timeout, ) - logger.debug("%s:%s created new sock %s", ip, port, id(sock)) + self.logger.debug("%s:%s created new sock %s", ip, port, id(sock)) if await sock.connect(): try: if await sock.authenticate(self.session_token): - logger.debug("sock auth successful %s", id(sock)) + self.logger.debug("sock auth successful %s", id(sock)) return sock except ASProtocolError as e: - logger.debug("sock auth failed %s", id(sock)) + self.logger.debug("sock auth failed %s", id(sock)) if e.as_response == ASResponse.SECURITY_NOT_ENABLED: # A user/pass was provided and security is disabled. This is OK # and a warning should have been displayed at login @@ -564,17 +567,19 @@ async def _get_connection(self, ip, port) -> ASSocket: ): # A node likely switched from security disabled to security enable. # In which case the error is caused by login never being called. - logger.debug("trying to sock login again %s", id(sock)) + self.logger.debug("trying to sock login again %s", id(sock)) self.perform_login = True await self.login() if await sock.authenticate(self.session_token): - logger.debug("sock auth successful on second try %s", id(sock)) + self.logger.debug( + "sock auth successful on second try %s", id(sock) + ) return sock await sock.close() raise - logger.debug("sock connect failed %s", id(sock)) + self.logger.debug("sock connect failed %s", id(sock)) return None async def close(self): @@ -632,7 +637,7 @@ async def _info_cinfo(self, command, ip=None, port=None): await sock.close() if result != -1 and result is not None: - logger.debug( + self.logger.debug( "%s:%s info cmd '%s' and sock %s returned %s", self.ip, self.port, @@ -649,7 +654,7 @@ async def _info_cinfo(self, command, ip=None, port=None): if sock: await sock.close() - logger.debug( + self.logger.debug( "%s:%s info cmd '%s' and sock %s raised %s for", self.ip, self.port, @@ -845,7 +850,7 @@ async def info_peers_flat_list(self): # post 3.10 services # @return_exceptions - def _info_service_helper(self, service, delimiter=";"): + def _info_service_helper(self, service, delimiter=","): if not service or isinstance(service, Exception): return [] s = [ @@ -881,9 +886,7 @@ async def info_service_list(self): Returns: list -- [(ip,port,tls_name),...] """ - return self._info_service_helper( - await self.info(self._get_service_info_call()), "," - ) + return self._info_service_helper(await self.info(self._get_service_info_call())) ###### Service End ###### diff --git a/lib/utils/conf.py b/lib/utils/conf.py index 62b81285..0f9453ae 100644 --- a/lib/utils/conf.py +++ b/lib/utils/conf.py @@ -665,6 +665,7 @@ def get_cli_args(): add_fn("-f", "--log-path") add_fn("-j", "--json", action="store_true") add_fn("--no-color", action="store_true") + add_fn("--debug", action="store_true") add_fn("--profile", action="store_true") add_fn("--single-node", action="store_true") add_fn("--line-separator", action="store_true") diff --git a/lib/utils/logger.py b/lib/utils/logger.py index 3420116e..5ef8698a 100644 --- a/lib/utils/logger.py +++ b/lib/utils/logger.py @@ -1,6 +1,11 @@ +from distutils import debug +from enum import Enum import logging import traceback from sys import exit +from typing import Optional +from xml.etree.ElementInclude import include +from lib.utils.logger_debug import DebugFormatter, get_debug_logger from lib.view import terminal @@ -21,6 +26,23 @@ def _handle_exception(self, msg): ): traceback.print_exc() + def debug(self, msg, *args, **kwargs): + include_traceback = ( + "include_traceback" in kwargs and kwargs["include_traceback"] + ) + + if include_traceback: + del kwargs["include_traceback"] + + super().debug(msg, *args, **kwargs) + + if ( + self.level <= logging.DEBUG + and include_traceback + and isinstance(msg, Exception) + ): + traceback.print_exc() + def error(self, msg, *args, **kwargs): super().error(msg, *args, **kwargs) @@ -31,7 +53,7 @@ def error(self, msg, *args, **kwargs): exit(2) def critical(self, msg, *args, **kwargs): - super().critical(msg, args, kwargs) + super().critical(msg, *args, **kwargs) if self.level <= logging.CRITICAL: self._handle_exception(msg) @@ -39,11 +61,16 @@ def critical(self, msg, *args, **kwargs): exit(1) -class LogFormatter(logging.Formatter): +class _LogColors(Enum): + red = "red" + yellow = "yellow" + + +class LogFormatter(DebugFormatter): def __init__(self, fmt="%(levelno)s: %(msg)s"): - super().__init__(fmt=fmt, datefmt=None, style="%") + super().__init__(fmt=fmt) - def _format_message(self, msg, level, color=None, *args): + def _format_message(self, msg, level, color: _LogColors, *args): try: message = str(msg).format(*args) except Exception: @@ -51,25 +78,31 @@ def _format_message(self, msg, level, color=None, *args): message = level + ": " + message - if color == "red": + if color == _LogColors.red: message = terminal.fg_red() + message + terminal.fg_clear() - if color == "yellow": + if color == _LogColors.yellow: message = terminal.fg_yellow() + message + terminal.fg_clear() return message def format(self, record: logging.LogRecord): if record.levelno == logging.DEBUG: - return self._format_message(record.msg, "DEBUG", None, *record.args) - elif record.levelno == logging.INFO: + return super().format(record) + if record.levelno == logging.INFO: return self._format_message(record.msg, "INFO", None, *record.args) elif record.levelno == logging.WARNING: - return self._format_message(record.msg, "WARNING", "yellow", *record.args) + return self._format_message( + record.msg, "WARNING", _LogColors.yellow, *record.args + ) elif record.levelno == logging.ERROR: - return self._format_message(record.msg, "ERROR", "red", *record.args) + return self._format_message( + record.msg, "ERROR", _LogColors.red, *record.args + ) elif record.levelno == logging.CRITICAL: - return self._format_message(record.msg, "ERROR", "red", *record.args) + return self._format_message( + record.msg, "ERROR", _LogColors.red, *record.args + ) formatter = logging.Formatter(self._style._fmt) return formatter.format(record) @@ -79,9 +112,9 @@ def format(self, record: logging.LogRecord): logging.basicConfig() logger = logging.getLogger("asadm") logger.propagate = False -logger.setLevel(logging.DEBUG) +logger.setLevel(logging.INFO) logging_handler = logging.StreamHandler() -logging_handler.setLevel(logging.INFO) +logging_handler.setLevel(logging.DEBUG) logging_handler.setFormatter(LogFormatter()) logger.addHandler(logging_handler) diff --git a/test/unit/live_cluster/client/test_cluster.py b/test/unit/live_cluster/client/test_cluster.py index bbf8e3d5..d84abbe2 100644 --- a/test/unit/live_cluster/client/test_cluster.py +++ b/test/unit/live_cluster/client/test_cluster.py @@ -60,9 +60,9 @@ async def info_cinfo_side_effect(*args, **kwargs): str(ip) + ":" + str(port) - + ";172.17.0.1:" + + ",172.17.0.1:" + str(port) - + ";172.17.1.1:" + + ",172.17.1.1:" + str(port) ), "peers-clear-std": "10,3000,[[BB9050011AC4202,,[172.17.0.1]],[BB9070011AC4202,,[[2001:db8:85a3::8a2e]:6666]]]", @@ -74,7 +74,7 @@ async def info_cinfo_side_effect(*args, **kwargs): str(ip) + ":" + str(port) - + ";192.168.120." + + ",192.168.120." + ip_last_digit + ":3000" ) @@ -84,7 +84,7 @@ async def info_cinfo_side_effect(*args, **kwargs): str(ip) + ":" + str(port) - + ";172.17.0.1:" + + ",172.17.0.1:" + str(port) + ",172.17.1.1:" + str(port)