From 77af8c0350dd186188cb2f7b5c6e9fec2f5e6c0f Mon Sep 17 00:00:00 2001 From: FredericBruening Date: Mon, 26 Feb 2024 12:47:33 -0500 Subject: [PATCH 01/33] Replace wildcard import with bespoke import --- bittensor/cli.py | 48 +++++++++++++++++++++++++++++- bittensor/extrinsics/delegation.py | 2 +- bittensor/mock/subtensor_mock.py | 2 +- bittensor/subtensor.py | 2 +- 4 files changed, 50 insertions(+), 4 deletions(-) diff --git a/bittensor/cli.py b/bittensor/cli.py index d8df0459af..c9b0e2b20a 100644 --- a/bittensor/cli.py +++ b/bittensor/cli.py @@ -20,7 +20,53 @@ import argparse import bittensor from typing import List, Optional -from .commands import * +from .commands import ( + AutocompleteCommand, + DelegateStakeCommand, + DelegateUnstakeCommand, + GetIdentityCommand, + GetWalletHistoryCommand, + InspectCommand, + ListCommand, + ListDelegatesCommand, + MetagraphCommand, + MyDelegatesCommand, + NewColdkeyCommand, + NewHotkeyCommand, + NominateCommand, + OverviewCommand, + PowRegisterCommand, + ProposalsCommand, + RegenColdkeyCommand, + RegenColdkeypubCommand, + RegenHotkeyCommand, + RegisterCommand, + RegisterSubnetworkCommand, + RootGetWeightsCommand, + RootList, + RootRegisterCommand, + RootSetBoostCommand, + RootSetSlashCommand, + RootSetWeightsCommand, + RunFaucetCommand, + SenateCommand, + SetIdentityCommand, + StakeCommand, + StakeShow, + SubnetGetHyperparamsCommand, + SubnetHyperparamsCommand, + SubnetListCommand, + SubnetLockCostCommand, + SubnetSudoCommand, + SwapHotkeyCommand, + TransferCommand, + UnStakeCommand, + UpdateCommand, + UpdateWalletCommand, + VoteCommand, + WalletBalanceCommand, + WalletCreateCommand, +) # Create a console instance for CLI display. console = bittensor.__console__ diff --git a/bittensor/extrinsics/delegation.py b/bittensor/extrinsics/delegation.py index 04dd2252db..93d99f18eb 100644 --- a/bittensor/extrinsics/delegation.py +++ b/bittensor/extrinsics/delegation.py @@ -17,7 +17,7 @@ # DEALINGS IN THE SOFTWARE. import bittensor -from ..errors import * +from ..errors import NominationError, NotDelegateError, NotRegisteredError, StakeError from rich.prompt import Confirm from typing import Union, Optional from bittensor.utils.balance import Balance diff --git a/bittensor/mock/subtensor_mock.py b/bittensor/mock/subtensor_mock.py index cf8f89b386..bf99fac474 100644 --- a/bittensor/mock/subtensor_mock.py +++ b/bittensor/mock/subtensor_mock.py @@ -34,7 +34,7 @@ SubnetInfo, AxonInfo, ) -from ..errors import * +from ..errors import ChainQueryError from ..subtensor import subtensor from ..utils import RAOPERTAO, U16_NORMALIZED_FLOAT from ..utils.balance import Balance diff --git a/bittensor/subtensor.py b/bittensor/subtensor.py index 60f4b4f4e3..55d65a32f3 100644 --- a/bittensor/subtensor.py +++ b/bittensor/subtensor.py @@ -46,7 +46,7 @@ IPInfo, custom_rpc_type_registry, ) -from .errors import * +from .errors import IdentityError, NominationError, StakeError from .extrinsics.network import ( register_subnetwork_extrinsic, set_hyperparameter_extrinsic, From d2f46fa7b73971e3422a52a204eb7efec336478a Mon Sep 17 00:00:00 2001 From: FredericBruening Date: Mon, 26 Feb 2024 12:47:56 -0500 Subject: [PATCH 02/33] Replace wildcard import with bespoke import --- bittensor/__init__.py | 87 ++++++++++++++++++++++++++++++++++++++----- 1 file changed, 78 insertions(+), 9 deletions(-) diff --git a/bittensor/__init__.py b/bittensor/__init__.py index c3d09be32e..701edfe317 100644 --- a/bittensor/__init__.py +++ b/bittensor/__init__.py @@ -206,25 +206,94 @@ def debug(on: bool = True): }, } -from .errors import * +from .errors import ( + BlacklistedException, + ChainConnectionError, + ChainError, + ChainQueryError, + ChainTransactionError, + IdentityError, + InternalServerError, + InvalidRequestNameError, + KeyFileError, + MetadataError, + NominationError, + NotDelegateError, + NotRegisteredError, + NotVerifiedException, + PostProcessException, + PriorityException, + RegistrationError, + RunException, + StakeError, + SynapseDendriteNoneException, + SynapseParsingError, + TransferError, + UnknownSynapseError, + UnstakeError, +) from substrateinterface import Keypair as Keypair -from .config import * -from .keyfile import * -from .wallet import * +from .config import InvalidConfigFile, DefaultConfig, config, T +from .keyfile import ( + serialized_keypair_to_keyfile_data, + deserialize_keypair_from_keyfile_data, + validate_password, + ask_password_to_encrypt, + keyfile_data_is_encrypted_nacl, + keyfile_data_is_encrypted_ansible, + keyfile_data_is_encrypted_legacy, + keyfile_data_is_encrypted, + keyfile_data_encryption_method, + legacy_encrypt_keyfile_data, + encrypt_keyfile_data, + get_coldkey_password_from_environment, + decrypt_keyfile_data, + keyfile, + Mockkeyfile, +) +from .wallet import display_mnemonic_msg, wallet + +from .utils import ( + ss58_to_vec_u8, + unbiased_topk, + version_checking, + strtobool, + strtobool_with_default, + get_explorer_root_url_by_network_from_map, + get_explorer_root_url_by_network_from_map, + get_explorer_url_for_network, + ss58_address_to_bytes, + U16_NORMALIZED_FLOAT, + U64_NORMALIZED_FLOAT, + u8_key_to_ss58, + hash, + wallet_utils, +) -from .utils import * from .utils.balance import Balance as Balance -from .chain_data import * +from .chain_data import ( + AxonInfo, + NeuronInfo, + NeuronInfoLite, + PrometheusInfo, + DelegateInfo, + StakeInfo, + SubnetInfo, + SubnetHyperparameters, + IPInfo, + ProposalCallData, + ProposalVoteData, +) from .subtensor import subtensor as subtensor from .cli import cli as cli, COMMANDS as ALL_COMMANDS from .btlogging import logging as logging from .metagraph import metagraph as metagraph from .threadpool import PriorityThreadPoolExecutor as PriorityThreadPoolExecutor -from .synapse import * -from .stream import * -from .tensor import * +from .synapse import TerminalInfo, Synapse +from .stream import StreamingSynapse +from .tensor import tensor, Tensor from .axon import axon as axon from .dendrite import dendrite as dendrite From a9d3c002c704f66806c0b84c83c814e4d4900ebd Mon Sep 17 00:00:00 2001 From: FredericBruening Date: Wed, 28 Feb 2024 13:32:02 -0500 Subject: [PATCH 03/33] Fix undefined parser var for print-completion print --- bittensor/cli.py | 1 + 1 file changed, 1 insertion(+) diff --git a/bittensor/cli.py b/bittensor/cli.py index c9b0e2b20a..b1b544b906 100644 --- a/bittensor/cli.py +++ b/bittensor/cli.py @@ -348,6 +348,7 @@ def run(self): """ # Check for print-completion argument if self.config.print_completion: + parser = cli.__create_parser__() shell = self.config.print_completion print(shtab.complete(parser, shell)) return From b9bb6fed3076e362bc37629d1dfa96887a6289d4 Mon Sep 17 00:00:00 2001 From: ifrit98 Date: Tue, 5 Mar 2024 19:09:04 +0000 Subject: [PATCH 04/33] handle req args by parsing and raising --- bittensor/config.py | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/bittensor/config.py b/bittensor/config.py index 52ea745e91..b40cdf5c65 100644 --- a/bittensor/config.py +++ b/bittensor/config.py @@ -123,6 +123,12 @@ def __init__( if args == None: args = sys.argv[1:] + # Check for missing required arguments before proceeding + missing_required_args = self.__check_for_missing_required_args(parser, args) + if missing_required_args: + # Handle missing required arguments gracefully + raise ValueError(f"Missing required arguments: {', '.join(missing_required_args)}") + # 1.1 Optionally load defaults if the --config is set. try: config_file_path = ( @@ -373,6 +379,20 @@ def is_set(self, param_name: str) -> bool: else: return self.get("__is_set")[param_name] + def __check_for_missing_required_args(self, parser: argparse.ArgumentParser, args: List[str]) -> List[str]: + required_args = self.__get_required_args_from_parser(parser) + missing_args = [arg for arg in required_args if not any(arg in s for s in args)] + return missing_args + + @staticmethod + def __get_required_args_from_parser(parser: argparse.ArgumentParser) -> List[str]: + required_args = [] + for action in parser._actions: + if action.required: + # Prefix the argument with '--' if it's a long argument, or '-' if it's short + prefix = '--' if len(action.dest) > 1 else '-' + required_args.append(prefix + action.dest) + return required_args T = TypeVar("T", bound="DefaultConfig") From 05a846d10297b2ea85f6cdee3616ffbfc3770ccf Mon Sep 17 00:00:00 2001 From: ifrit98 Date: Wed, 6 Mar 2024 20:10:43 +0000 Subject: [PATCH 05/33] black --- bittensor/config.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/bittensor/config.py b/bittensor/config.py index b40cdf5c65..59ad4451b8 100644 --- a/bittensor/config.py +++ b/bittensor/config.py @@ -127,7 +127,9 @@ def __init__( missing_required_args = self.__check_for_missing_required_args(parser, args) if missing_required_args: # Handle missing required arguments gracefully - raise ValueError(f"Missing required arguments: {', '.join(missing_required_args)}") + raise ValueError( + f"Missing required arguments: {', '.join(missing_required_args)}" + ) # 1.1 Optionally load defaults if the --config is set. try: @@ -379,7 +381,9 @@ def is_set(self, param_name: str) -> bool: else: return self.get("__is_set")[param_name] - def __check_for_missing_required_args(self, parser: argparse.ArgumentParser, args: List[str]) -> List[str]: + def __check_for_missing_required_args( + self, parser: argparse.ArgumentParser, args: List[str] + ) -> List[str]: required_args = self.__get_required_args_from_parser(parser) missing_args = [arg for arg in required_args if not any(arg in s for s in args)] return missing_args @@ -390,10 +394,11 @@ def __get_required_args_from_parser(parser: argparse.ArgumentParser) -> List[str for action in parser._actions: if action.required: # Prefix the argument with '--' if it's a long argument, or '-' if it's short - prefix = '--' if len(action.dest) > 1 else '-' + prefix = "--" if len(action.dest) > 1 else "-" required_args.append(prefix + action.dest) return required_args + T = TypeVar("T", bound="DefaultConfig") From e9de4c145bc535ad155c25807c3ff6f740693479 Mon Sep 17 00:00:00 2001 From: ifrit98 Date: Wed, 20 Mar 2024 19:25:45 +0000 Subject: [PATCH 06/33] update documentation for serving rate limit --- bittensor/subtensor.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bittensor/subtensor.py b/bittensor/subtensor.py index d43973b94e..90ceefd76d 100644 --- a/bittensor/subtensor.py +++ b/bittensor/subtensor.py @@ -3109,7 +3109,7 @@ def serving_rate_limit( ) -> Optional[int]: """ Retrieves the serving rate limit for a specific subnet within the Bittensor network. - This rate limit determines the maximum number of requests a neuron can serve within a given time frame. + This rate limit determines how often you can change your node's IP address on the blockchain. Expressed in number of blocks. Applies to both subnet validator and subnet miner nodes. Used when you move your node to a new machine. Args: netuid (int): The unique identifier of the subnet. From ac951032a9a6bc94f63b7e046527a582e241dcfe Mon Sep 17 00:00:00 2001 From: ifrit98 Date: Wed, 20 Mar 2024 19:27:34 +0000 Subject: [PATCH 07/33] fix return type for _do_swap_hotkey --- bittensor/subtensor.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/bittensor/subtensor.py b/bittensor/subtensor.py index 90ceefd76d..5a2e725d7b 100644 --- a/bittensor/subtensor.py +++ b/bittensor/subtensor.py @@ -1018,7 +1018,7 @@ def make_substrate_call_with_retry(): # We only wait here if we expect finalization. if not wait_for_finalization and not wait_for_inclusion: - return True + return True, None # process if registration successful, try again if pow is still valid response.process_events() @@ -1060,7 +1060,7 @@ def make_substrate_call_with_retry(): # We only wait here if we expect finalization. if not wait_for_finalization and not wait_for_inclusion: - return True + return True, None # process if registration successful, try again if pow is still valid response.process_events() From d5348b9fac5facf3fc2ee03c8ecc668d349f4f1c Mon Sep 17 00:00:00 2001 From: josh Date: Thu, 21 Mar 2024 11:46:57 -0500 Subject: [PATCH 08/33] fix: nonce implementation --- bittensor/axon.py | 23 +++++++++++++++++------ bittensor/dendrite.py | 2 +- bittensor/synapse.py | 6 +++--- 3 files changed, 21 insertions(+), 10 deletions(-) diff --git a/bittensor/axon.py b/bittensor/axon.py index 1301b32c8d..34ce9e51f1 100644 --- a/bittensor/axon.py +++ b/bittensor/axon.py @@ -914,14 +914,25 @@ async def default_verify(self, synapse: bittensor.Synapse): # Build the unique endpoint key. endpoint_key = f"{synapse.dendrite.hotkey}:{synapse.dendrite.uuid}" - # Check the nonce from the endpoint key. + # Check the nonce from the endpoint key with 4 second delta + allowedDelta = 4000000000 + + # Requests must have nonces to be safe from replays + if synapse.dendrite.nonce is None: + raise Exception("Missing Nonce") + + # If we don't have a nonce stored, ensure that the nonce falls within + # a reasonable delta. + if ( + self.nonces.get(endpoint_key) is None + and synapse.dendrite.nonce <= time.time_ns() - allowedDelta + ): + raise Exception("Nonce is too old") if ( - endpoint_key in self.nonces.keys() - and self.nonces[endpoint_key] is not None - and synapse.dendrite.nonce is not None + self.nonces.get(endpoint_key) is not None and synapse.dendrite.nonce <= self.nonces[endpoint_key] ): - raise Exception("Nonce is too small") + raise Exception("Nonce is too old") if not keypair.verify(message, synapse.dendrite.signature): raise Exception( @@ -1190,7 +1201,7 @@ async def preprocess(self, request: Request) -> bittensor.Synapse: { "version": str(bittensor.__version_as_int__), "uuid": str(self.axon.uuid), - "nonce": f"{time.monotonic_ns()}", + "nonce": f"{time.time_ns()}", "status_message": "Success", "status_code": "100", } diff --git a/bittensor/dendrite.py b/bittensor/dendrite.py index 2b7afee5ef..b5e8df9a28 100644 --- a/bittensor/dendrite.py +++ b/bittensor/dendrite.py @@ -658,7 +658,7 @@ def preprocess_synapse_for_request( synapse.dendrite = bittensor.TerminalInfo( ip=self.external_ip, version=bittensor.__version_as_int__, - nonce=time.monotonic_ns(), + nonce=time.time_ns(), uuid=self.uuid, hotkey=self.keypair.ss58_address, ) diff --git a/bittensor/synapse.py b/bittensor/synapse.py index d4f210670e..6b7af3d765 100644 --- a/bittensor/synapse.py +++ b/bittensor/synapse.py @@ -114,7 +114,7 @@ class TerminalInfo(pydantic.BaseModel): ip (str): IP address of the terminal, crucial for network routing and data transmission. port (int): Network port used by the terminal, key for establishing network connections. version (int): Bittensor version running on the terminal, ensuring compatibility between different nodes in the network. - nonce (int): Unique, monotonically increasing number for each terminal, aiding in identifying and ordering network interactions. + nonce (int): Unix timestamp that linearly increases for each request, ensuring requests cannot be duplicated or repeated uuid (str): Unique identifier for the terminal, fundamental for network security and identification. hotkey (str): Encoded hotkey string of the terminal wallet, important for transaction and identity verification in the network. signature (str): Digital signature verifying the tuple of nonce, axon_hotkey, dendrite_hotkey, and uuid, critical for ensuring data authenticity and security. @@ -211,10 +211,10 @@ class Config: cast_int ) - # A unique monotonically increasing integer nonce associate with the terminal + # A Unix timestamp to associate with the terminal nonce: Optional[int] = pydantic.Field( title="nonce", - description="A unique monotonically increasing integer nonce associate with the terminal generated from time.monotonic_ns()", + description="A Unix timestamp that prevents replay attacks", examples=111111, default=None, allow_mutation=True, From 4959bf08b58f113353cef54204d9a2d4fbf82459 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Wed, 13 Mar 2024 15:50:41 -0400 Subject: [PATCH 09/33] First commit for stdout stream with builtin logging module --- bittensor/logging/__init__.py | 216 +++++++++++++++++++++++++++++++ bittensor/logging/format.py | 96 ++++++++++++++ bittensor/logging/helpers.py | 43 ++++++ bittensor/logging/logging.md | 5 + tests/unit_tests/test_logging.py | 66 ++++++++++ 5 files changed, 426 insertions(+) create mode 100644 bittensor/logging/__init__.py create mode 100644 bittensor/logging/format.py create mode 100644 bittensor/logging/helpers.py create mode 100644 bittensor/logging/logging.md create mode 100644 tests/unit_tests/test_logging.py diff --git a/bittensor/logging/__init__.py b/bittensor/logging/__init__.py new file mode 100644 index 0000000000..a21c5df1a3 --- /dev/null +++ b/bittensor/logging/__init__.py @@ -0,0 +1,216 @@ +import os +import sys +import time +import logging +import argparse +from typing import Optional, NamedTuple + +import bittensor.config +from bittensor.logging.format import BtStreamFormatter +from bittensor.logging.helpers import all_loggers + + +BASE_LOG_FORMAT = "%(asctime)s | %(levelname)s | %(message)s" +DATE_FORMAT = "%Y-%m-%d %H:%M:%S" +BITTENSOR_LOGGER_NAME = "bittensor" + + +class LoggingConfig(NamedTuple): + debug: bool + trace: bool + logging_dir: str + record_log: bool + + +def __enable_logger_and_set_bt_format( + logger: logging.Logger, + log_level: int=logging.INFO, + logfile: str="bittensor.log" +): + handler = logging.StreamHandler(stream=sys.stdout) + handler.setFormatter(BtStreamFormatter(BASE_LOG_FORMAT, DATE_FORMAT)) + handler.setLevel(log_level) + handler.formatter.set_trace(True) + + logger.addHandler(handler) + logger.setLevel(log_level) + + +def getLogger(name: str = BITTENSOR_LOGGER_NAME): + logger = logging.getLogger(name) + for handler in logger.handlers[:]: + if isinstance(handler, logging.StreamHandler): + logger.removeHandler(handler) + + handler = logging.StreamHandler(stream=sys.stdout) + handler.setLevel(logging.INFO) + handler.setFormatter(BtStreamFormatter(BASE_LOG_FORMAT, DATE_FORMAT)) + logger.addHandler(handler) + logger.setLevel(logging.INFO) + + return logger + + +def set_trace(on: bool=True): + bt_logger = logging.getLogger(BITTENSOR_LOGGER_NAME) + if on: + for logger in all_loggers(): + __enable_logger_and_set_bt_format(logger, log_level=logging.TRACE) + else: + __set_default_logging(bt_logger) + for logger in all_loggers(): + if logger.name is BITTENSOR_LOGGER_NAME: + __set_default_logging(logger) + __disable_logger(logger) + + +def set_debug(on: bool=True): + if on: + for logger in all_loggers(): + __enable_logger(level=logging.DEBUG) + else: + for logger in all_loggers(): + if logger.name is BITTENSOR_LOGGER_NAME: + __set_default_logging(logger) + __disable_logger(logger) + + +def __disable_logger(logger: logging.Logger): + logger.setLevel(logging.CRITICAL) + for handler in logger.handlers: + if isinstance(handler.formatter, BtStreamFormatter): + handler.formatter.set_trace(False) + else: + logger.removeHandler(handler) + + +def __enable_debug(logger: logging.Logger): + pass + + +def __set_default_logging_global(): + for logger in all_loggers(): + if logger.name == BITTENSOR_LOGGER_NAME: + __set_default_logging(logger) + else: + __disable_logger(logger) + + +def __disable_third_party_loggers(): + for logger in all_loggers(): + if logger.name == BITTENSOR_LOGGER_NAME: + continue + __disable_logger(logger) + + +def __set_default_logging(logger: logging.Logger): + logger.setLevel(logging.INFO) + for handler in logger.handlers: + if isinstance(handler.formatter, BtStreamFormatter): + handler.setLevel(logging.INFO) + handler.formatter.set_trace(False) + + +def on(): + logger = logging.getLogger(BITTENSOR_LOGGER_NAME) + __enable_logger_and_set_bt_format(logger, logging.INFO) + + +def off(): + for logger in all_loggers(): + __disable_logger(logger) + + +def add_args(cls, parser: argparse.ArgumentParser, prefix: str = None): + """Accept specific arguments fro parser""" + prefix_str = "" if prefix == None else prefix + "." + try: + default_logging_debug = os.getenv("BT_LOGGING_DEBUG") or False + default_logging_trace = os.getenv("BT_LOGGING_TRACE") or False + default_logging_record_log = os.getenv("BT_LOGGING_RECORD_LOG") or False + default_logging_logging_dir = ( + os.getenv("BT_LOGGING_LOGGING_DIR") or "~/.bittensor/miners" + ) + parser.add_argument( + "--" + prefix_str + "logging.debug", + action="store_true", + help="""Turn on bittensor debugging information""", + default=default_logging_debug, + ) + parser.add_argument( + "--" + prefix_str + "logging.trace", + action="store_true", + help="""Turn on bittensor trace level information""", + default=default_logging_trace, + ) + parser.add_argument( + "--" + prefix_str + "logging.record_log", + action="store_true", + help="""Turns on logging to file.""", + default=default_logging_record_log, + ) + parser.add_argument( + "--" + prefix_str + "logging.logging_dir", + type=str, + help="Logging default root directory.", + default=default_logging_logging_dir, + ) + except argparse.ArgumentError: + # re-parsing arguments. + pass + + +def config(cls): + """Get config from the argument parser. + + Return: + bittensor.config object + """ + parser = argparse.ArgumentParser() + add_args(parser) + return bittensor.config(parser, args=[]) + + + +logger = getLogger(BITTENSOR_LOGGER_NAME) + + +# class btlogging: +# @classmethod +# def on(cls): +# """Turn on logging output by re-adding the sinks.""" +# if cls.__off__: +# cls.__off__ = False + +# cls.__std_sink__ = logging.StreamHandler( +# sys.stdout, +# colorize=True, +# enqueue=True, +# backtrace=True, +# diagnose=True, +# format=cls.log_formatter, +# ) +# cls.__std_sink__.setLevel(logging.NOTSET) + +# logger.addHandler(cls.__std_sink__) + +# # Check if logging to file was originally enabled and re-add the file sink +# if cls.__file_sink__ is not None: +# config = cls.config() +# filepath = config.logging.logging_dir + "/logs.log" +# cls.__file_sink__ = logging.FileHandler( +# filepath, +# enqueue=True, +# backtrace=True, +# diagnose=True, +# format=cls.log_save_formatter, +# rotation="25 MB", +# retention="10 days", +# ) +# logging.addHandler(cls.__file_sink__) + +# cls.set_debug(cls.__debug_on__) +# cls.set_trace(cls.__trace_on__) + + + diff --git a/bittensor/logging/format.py b/bittensor/logging/format.py new file mode 100644 index 0000000000..a86771a43b --- /dev/null +++ b/bittensor/logging/format.py @@ -0,0 +1,96 @@ +import time +import logging +from colorama import ( + init, + Fore, + Back, + Style +) + +from bittensor.logging.helpers import get_max_logger_name_length + +init(autoreset=True) + + +TRACE_LEVELV_NUM = 5 +SUCCESS_LEVELV_NUM = 21 + + +def trace(self, message, *args, **kws): + if self.isEnabledFor(TRACE_LEVELV_NUM): + self._log(TRACE_LEVELV_NUM, message, args, **kws) + +def success(self, message, *args, **kws): + if self.isEnabledFor(SUCCESS_LEVELV_NUM): + self._log(SUCCESS_LEVELV_NUM, message, args, **kws) + + +logging.SUCCESS = SUCCESS_LEVELV_NUM +logging.addLevelName(SUCCESS_LEVELV_NUM, "SUCCESS") +logging.Logger.success = success + +logging.TRACE = TRACE_LEVELV_NUM +logging.addLevelName(TRACE_LEVELV_NUM, "TRACE") +logging.Logger.trace = trace + + +log_level_color_prefix = { + logging.NOTSET: Fore.RESET, + logging.TRACE: Fore.MAGENTA, + logging.DEBUG: Fore.BLUE, + logging.INFO: Fore.WHITE, + logging.SUCCESS: Fore.GREEN, + logging.WARNING: Fore.YELLOW, + logging.ERROR: Fore.RED, + logging.CRITICAL: Back.RED, +} + + +LOG_FORMATS = { + level: f"{Fore.BLUE}%(asctime)s{Fore.RESET} | {Style.BRIGHT}{color}%(levelname)s\033[0m | %(message)s" + for level, color in log_level_color_prefix.items() +} + +LOG_TRACE_FORMATS = { + level: f"{Fore.BLUE}%(asctime)s{Fore.RESET}"\ + f" | {Style.BRIGHT}{color}%(levelname)s{Fore.RESET}{Back.RESET}{Style.RESET_ALL}"\ + f" | %(name)s:%(filename)s:%(lineno)s"\ + f" | %(message)s" + for level, color in log_level_color_prefix.items() +} + + +class BtStreamFormatter(logging.Formatter): + trace = False + + def formatTime(self, record, datefmt=None): + """ + Override formatTime to add milliseconds. + """ + created = self.converter(record.created) + if datefmt: + s = time.strftime(datefmt, created) + else: + s = time.strftime("%Y-%m-%d %H:%M:%S", created) + s += ".{:03d}".format(int(record.msecs)) + return s + + def format(self, record): + # Save the original format configured by the user + # when the logger formatter was instantiated + format_orig = self._style._fmt + spacing = get_max_logger_name_length() + 2 + record.levelname = f"{record.levelname:^16}" + # record.name = f"{record.name:^28}" + if self.trace is True: + self._style._fmt = LOG_TRACE_FORMATS[record.levelno] + else: + self._style._fmt = LOG_FORMATS[record.levelno] + result = super().format(record) + self._style._fmt = format_orig + + return result + + def set_trace(self, state: bool = True): + + self.trace = state \ No newline at end of file diff --git a/bittensor/logging/helpers.py b/bittensor/logging/helpers.py new file mode 100644 index 0000000000..e81ca36375 --- /dev/null +++ b/bittensor/logging/helpers.py @@ -0,0 +1,43 @@ +import logging + +def all_loggers(): + """ + Generator that yields all logger instances in the application. + """ + for logger in logging.root.manager.loggerDict.values(): + if isinstance(logger, logging.PlaceHolder): + continue + # In some versions of Python, the values in loggerDict might be + # LoggerAdapter instances instead of Logger instances. + # We check for Logger instances specifically. + if isinstance(logger, logging.Logger): + yield logger + else: + # If it's not a Logger instance, it could be a LoggerAdapter or + # another form that doesn't directly offer logging methods. + # This branch can be extended to handle such cases as needed. + pass + + +def all_logger_names(): + for name, logger in logging.root.manager.loggerDict.items(): + if isinstance(logger, logging.PlaceHolder): + continue + # In some versions of Python, the values in loggerDict might be + # LoggerAdapter instances instead of Logger instances. + # We check for Logger instances specifically. + if isinstance(logger, logging.Logger): + yield name + else: + # If it's not a Logger instance, it could be a LoggerAdapter or + # another form that doesn't directly offer logging methods. + # This branch can be extended to handle such cases as needed. + pass + + +def get_max_logger_name_length(): + max_length = 0 + for name in all_logger_names(): + if len(name) > max_length: + max_length = len(name) + return max_length \ No newline at end of file diff --git a/bittensor/logging/logging.md b/bittensor/logging/logging.md new file mode 100644 index 0000000000..0470c5f5bb --- /dev/null +++ b/bittensor/logging/logging.md @@ -0,0 +1,5 @@ +# Sequence Diagram + +```mermaid + +``` \ No newline at end of file diff --git a/tests/unit_tests/test_logging.py b/tests/unit_tests/test_logging.py new file mode 100644 index 0000000000..7a740f02ba --- /dev/null +++ b/tests/unit_tests/test_logging.py @@ -0,0 +1,66 @@ +import logging +import pytest + +from bittensor.logging import ( + getLogger, + trace, + __enable_non_bt_loggers, + __disable_non_bt_loggers, + __enable_trace, + __disable_logger, + __set_default_logging, + __set_bt_format_logger, + BITTENSOR_LOGGER_NAME +) +from bittensor.logging.format import BtStreamFormatter + + +# Mock for all_loggers function +@pytest.fixture +def all_loggers_mock(mocker): + mock = mocker.patch('your_module.all_loggers') + mock.return_value = [logging.getLogger(name) for name in ['test_logger1', 'test_logger2']] + return mock + +def test_getLogger(mock_stdout): + logger = getLogger('testLogger') + + +def test_trace_enable(mocker, mock_stdout): + bt_logger = logging.getLogger(BITTENSOR_LOGGER_NAME) + trace() + # This assumes TRACE is a custom level you've set somewhere as logging.TRACE might not be a default level + assert bt_logger.level == logging.TRACE # Use DEBUG for illustration + +def test_enable_non_bt_loggers(all_loggers_mock, mock_stdout): + __enable_non_bt_loggers() + for logger in all_loggers(): + if logger.name != BITTENSOR_LOGGER_NAME: + assert logger.level == logging.INFO # Assuming INFO is the default + assert any([handler.formatter is BtStreamFormatter for handler in logger.handlers]) + +def test_disable_non_bt_loggers(all_loggers_mock, mock_stdout): + __disable_non_bt_loggers() + for logger in all_loggers_mock.return_value: + if logger.name != BITTENSOR_LOGGER_NAME: + assert logger.level == logging.CRITICAL + +def test_enable_trace(mock_stdout): + logger = logging.getLogger('test_trace') + __enable_trace(logger) + # Assuming TRACE level and checking if formatter's trace is enabled + for handler in logger.handlers: + assert isinstance(handler.formatter, BtStreamFormatter) + assert handler.formatter.trace_enabled == True + +def test_disable_logger(mock_stdout): + logger = logging.getLogger('test_disable') + __disable_logger(logger) + # Assuming disabling sets level to CRITICAL and trace to False + assert logger.level == logging.CRITICAL + for handler in logger.handlers: + assert isinstance(handler.formatter, BtStreamFormatter) + assert handler.formatter.trace_enabled == False + +# Further tests would continue in this manner, focusing on the behavior expected from each function. + From 953274be99eef2236dda220c04829b681cf66795 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 14 Mar 2024 17:14:24 -0400 Subject: [PATCH 10/33] Remove loguru from btlogging. To enable and manage third party loggers, loguru needed to be replaced with the builtin logging library. To maintain functional parity and best manage the logging infra state, the new log manager was built using a state machine, in order to explicitly handle transitions between the various logger states. --- bittensor/__init__.py | 5 +- bittensor/btlogging.py | 350 -------------------- bittensor/btlogging/__init__.py | 78 +++++ bittensor/btlogging/defines.py | 7 + bittensor/{logging => btlogging}/format.py | 5 +- bittensor/{logging => btlogging}/helpers.py | 0 bittensor/btlogging/loggingmachine.py | 255 ++++++++++++++ bittensor/logging/__init__.py | 216 ------------ bittensor/logging/logging.md | 5 - 9 files changed, 344 insertions(+), 577 deletions(-) delete mode 100644 bittensor/btlogging.py create mode 100644 bittensor/btlogging/__init__.py create mode 100644 bittensor/btlogging/defines.py rename bittensor/{logging => btlogging}/format.py (95%) rename bittensor/{logging => btlogging}/helpers.py (100%) create mode 100644 bittensor/btlogging/loggingmachine.py delete mode 100644 bittensor/logging/__init__.py delete mode 100644 bittensor/logging/logging.md diff --git a/bittensor/__init__.py b/bittensor/__init__.py index 3fa52264f0..5105141b68 100644 --- a/bittensor/__init__.py +++ b/bittensor/__init__.py @@ -287,7 +287,8 @@ def debug(on: bool = True): ) from .subtensor import subtensor as subtensor from .cli import cli as cli, COMMANDS as ALL_COMMANDS -from .btlogging import logging as logging +from .btlogging import logging +# from .logging import LoggingMachine, from .metagraph import metagraph as metagraph from .threadpool import PriorityThreadPoolExecutor as PriorityThreadPoolExecutor @@ -308,6 +309,6 @@ def debug(on: bool = True): subtensor.config(), PriorityThreadPoolExecutor.config(), wallet.config(), - logging.config(), + logging.config, ] defaults = config.merge_all(configs) diff --git a/bittensor/btlogging.py b/bittensor/btlogging.py deleted file mode 100644 index 0965aea347..0000000000 --- a/bittensor/btlogging.py +++ /dev/null @@ -1,350 +0,0 @@ -""" Standardized logging for Bittensor. -""" - -# The MIT License (MIT) -# Copyright © 2021 Yuma Rao - -# Permission is hereby granted, free of charge, to any person obtaining a copy of this software and associated -# documentation files (the “Software”), to deal in the Software without restriction, including without limitation -# the rights to use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the Software, -# and to permit persons to whom the Software is furnished to do so, subject to the following conditions: - -# The above copyright notice and this permission notice shall be included in all copies or substantial portions of -# the Software. - -# THE SOFTWARE IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO -# THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL -# THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION -# OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER -# DEALINGS IN THE SOFTWARE. - -import os -import sys -import copy -import torch -import argparse -import bittensor - -from loguru import logger - -logger = logger.opt(colors=True) -# Remove default sink. -try: - logger.remove(0) -except Exception: - pass - -import re - - -def _remove_loguru_ansi_directive(text: str) -> str: - pattern = r"<.*?>" - return re.sub(pattern, "", text) - - -class logging: - """Standardized logging for Bittensor.""" - - __has_been_inited__: bool = False - __debug_on__: bool = False - __trace_on__: bool = False - __std_sink__: int = None - __file_sink__: int = None - __off__: bool = False - - @classmethod - def off(cls): - """Turn off all logging output.""" - if not cls.__has_been_inited__: - cls() - cls.__off__ = True - - for handler_id in list(logger._core.handlers): - logger.remove(handler_id) - - @classmethod - def on(cls): - """Turn on logging output by re-adding the sinks.""" - if cls.__off__: - cls.__off__ = False - - cls.__std_sink__ = logger.add( - sys.stdout, - level=0, - filter=cls.log_filter, - colorize=True, - enqueue=True, - backtrace=True, - diagnose=True, - format=cls.log_formatter, - ) - - # Check if logging to file was originally enabled and re-add the file sink - if cls.__file_sink__ is not None: - config = cls.config() - filepath = config.logging.logging_dir + "/logs.log" - cls.__file_sink__ = logger.add( - filepath, - filter=cls.log_save_filter, - enqueue=True, - backtrace=True, - diagnose=True, - format=cls.log_save_formatter, - rotation="25 MB", - retention="10 days", - ) - - cls.set_debug(cls.__debug_on__) - cls.set_trace(cls.__trace_on__) - - def __new__( - cls, - config: "bittensor.config" = None, - debug: bool = None, - trace: bool = None, - record_log: bool = None, - logging_dir: str = None, - ): - r"""Instantiate Bittensor logging system backend. - - Args: - config (bittensor.config, optional): - bittensor.logging.config() - debug (bool, optional): - Turn on debug. - trace (bool, optional): - Turn on trace. - record_log (bool, optional): - If true, logs are saved to loggind dir. - logging_dir (str, optional): - Directory where logs are sunk. - """ - - cls.__has_been_inited__ = True - - if config == None: - config = logging.config() - config = copy.deepcopy(config) - config.logging.debug = debug if debug != None else config.logging.debug - config.logging.trace = trace if trace != None else config.logging.trace - config.logging.record_log = ( - record_log if record_log != None else config.logging.record_log - ) - config.logging.logging_dir = ( - logging_dir if logging_dir != None else config.logging.logging_dir - ) - - # Remove default sink. - try: - logger.remove(0) - except Exception: - pass - - # Optionally Remove other sinks. - if cls.__std_sink__ != None: - logger.remove(cls.__std_sink__) - if cls.__file_sink__ != None: - logger.remove(cls.__file_sink__) - - # Add filtered sys.stdout. - cls.__std_sink__ = logger.add( - sys.stdout, - level=0, - filter=cls.log_filter, - colorize=True, - enqueue=True, - backtrace=True, - diagnose=True, - format=cls.log_formatter, - ) - - cls.set_debug(config.logging.debug) - cls.set_trace(config.logging.trace) - - # ---- Setup logging to root ---- - if config.logging.record_log: - filepath = config.logging.logging_dir + "/logs.log" - cls.__file_sink__ = logger.add( - filepath, - filter=cls.log_save_filter, - enqueue=True, - backtrace=True, - diagnose=True, - format=cls.log_save_formatter, - rotation="25 MB", - retention="10 days", - ) - - @classmethod - def config(cls): - """Get config from the argument parser. - - Return: - bittensor.config object - """ - parser = argparse.ArgumentParser() - logging.add_args(parser) - return bittensor.config(parser, args=[]) - - @classmethod - def help(cls): - """Print help to stdout""" - parser = argparse.ArgumentParser() - cls.add_args(parser) - print(cls.__new__.__doc__) - parser.print_help() - - @classmethod - def add_args(cls, parser: argparse.ArgumentParser, prefix: str = None): - """Accept specific arguments fro parser""" - prefix_str = "" if prefix == None else prefix + "." - try: - default_logging_debug = os.getenv("BT_LOGGING_DEBUG") or False - default_logging_trace = os.getenv("BT_LOGGING_TRACE") or False - default_logging_record_log = os.getenv("BT_LOGGING_RECORD_LOG") or False - default_logging_logging_dir = ( - os.getenv("BT_LOGGING_LOGGING_DIR") or "~/.bittensor/miners" - ) - parser.add_argument( - "--" + prefix_str + "logging.debug", - action="store_true", - help="""Turn on bittensor debugging information""", - default=default_logging_debug, - ) - parser.add_argument( - "--" + prefix_str + "logging.trace", - action="store_true", - help="""Turn on bittensor trace level information""", - default=default_logging_trace, - ) - parser.add_argument( - "--" + prefix_str + "logging.record_log", - action="store_true", - help="""Turns on logging to file.""", - default=default_logging_record_log, - ) - parser.add_argument( - "--" + prefix_str + "logging.logging_dir", - type=str, - help="Logging default root directory.", - default=default_logging_logging_dir, - ) - except argparse.ArgumentError: - # re-parsing arguments. - pass - - @classmethod - def check_config(cls, config: "bittensor.config"): - """Check config""" - assert config.logging - - @classmethod - def set_debug(cls, debug_on: bool = True): - """Set debug for the specific cls class""" - if not cls.__has_been_inited__: - cls() - cls.__debug_on__ = debug_on - - @classmethod - def set_trace(cls, trace_on: bool = True): - """Set trace back for the specific cls class""" - if not cls.__has_been_inited__: - cls() - cls.__trace_on__ = trace_on - - @classmethod - def get_level(cls) -> int: - return 5 if cls.__trace_on__ else 10 if cls.__debug_on__ else 20 - - @classmethod - def log_filter(cls, record): - """Filter out debug log if debug is not on""" - if cls.get_level() <= record["level"].no: - return True - else: - return False - - @classmethod - def log_save_filter(cls, record): - if cls.get_level() < record["level"].no: - return True - else: - return False - - @classmethod - def log_formatter(cls, record): - """Log with different format according to record['extra']""" - return "{time:YYYY-MM-DD HH:mm:ss.SSS} | {level: ^16} | {message}\n" - - @classmethod - def log_save_formatter(cls, record): - if cls.__trace_on__: - return "{time:YYYY-MM-DD HH:mm:ss.SSS} | {level: ^16} | {name}:{function}:{line} | {message}\n" - else: - return "{time:YYYY-MM-DD HH:mm:ss.SSS} | {level: ^16} | {message}\n" - - @classmethod - def _format(cls, prefix: object, sufix: object = None): - """Format logging message""" - if isinstance(prefix, torch.Tensor): - prefix = prefix.detach() - if sufix != None: - if isinstance(sufix, torch.Tensor): - sufix = "shape: {}".format(str(sufix.shape)) + " data: {}".format( - str(sufix.detach()) - ) - else: - sufix = "{}".format(str(sufix)) - else: - sufix = "" - log_msg = str(prefix).ljust(30) + str(sufix) - return _remove_loguru_ansi_directive(log_msg) - - @classmethod - def success(cls, prefix: object, sufix: object = None): - """Success logging""" - if not cls.__has_been_inited__: - cls() - logger.success(cls._format(prefix, sufix)) - - @classmethod - def warning(cls, prefix: object, sufix: object = None): - """Warning logging""" - if not cls.__has_been_inited__: - cls() - logger.warning(cls._format(prefix, sufix)) - - @classmethod - def error(cls, prefix: object, sufix: object = None): - """Error logging""" - if not cls.__has_been_inited__: - cls() - logger.error(cls._format(prefix, sufix)) - - @classmethod - def info(cls, prefix: object, sufix: object = None): - """Info logging""" - if not cls.__has_been_inited__: - cls() - logger.info(cls._format(prefix, sufix)) - - @classmethod - def debug(cls, prefix: object, sufix: object = None): - """Info logging""" - if not cls.__has_been_inited__: - cls() - logger.debug(cls._format(prefix, sufix)) - - @classmethod - def trace(cls, prefix: object, sufix: object = None): - """Info logging""" - if not cls.__has_been_inited__: - cls() - logger.trace(cls._format(prefix, sufix)) - - @classmethod - def exception(cls, prefix: object, sufix: object = None): - """Exception logging with traceback""" - if not cls.__has_been_inited__: - cls() - logger.exception(cls._format(prefix, sufix)) diff --git a/bittensor/btlogging/__init__.py b/bittensor/btlogging/__init__.py new file mode 100644 index 0000000000..670088f2c2 --- /dev/null +++ b/bittensor/btlogging/__init__.py @@ -0,0 +1,78 @@ +""" +Standardized logging for Bittensor. +""" + +# The MIT License (MIT) +# Copyright © 2021 Yuma Rao + +# Permission is hereby granted, free of charge, to any person obtaining a copy of this software and associated +# documentation files (the “Software”), to deal in the Software without restriction, including without limitation +# the rights to use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the Software, +# and to permit persons to whom the Software is furnished to do so, subject to the following conditions: + +# The above copyright notice and this permission notice shall be included in all copies or substantial portions of +# the Software. + +# THE SOFTWARE IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO +# THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL +# THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION +# OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER +# DEALINGS IN THE SOFTWARE. + +import os +import argparse + +import bittensor.config +from bittensor.btlogging.loggingmachine import LoggingMachine + + +def add_args(parser: argparse.ArgumentParser, prefix: str = None): + """Accept specific arguments fro parser""" + prefix_str = "" if prefix == None else prefix + "." + try: + default_logging_debug = os.getenv("BT_LOGGING_DEBUG") or False + default_logging_trace = os.getenv("BT_LOGGING_TRACE") or False + default_logging_record_log = os.getenv("BT_LOGGING_RECORD_LOG") or False + default_logging_logging_dir = ( + os.getenv("BT_LOGGING_LOGGING_DIR") or "~/.bittensor/miners" + ) + parser.add_argument( + "--" + prefix_str + "logging.debug", + action="store_true", + help="""Turn on bittensor debugging information""", + default=default_logging_debug, + ) + parser.add_argument( + "--" + prefix_str + "logging.trace", + action="store_true", + help="""Turn on bittensor trace level information""", + default=default_logging_trace, + ) + parser.add_argument( + "--" + prefix_str + "logging.record_log", + action="store_true", + help="""Turns on logging to file.""", + default=default_logging_record_log, + ) + parser.add_argument( + "--" + prefix_str + "logging.logging_dir", + type=str, + help="Logging default root directory.", + default=default_logging_logging_dir, + ) + except argparse.ArgumentError: + # re-parsing arguments. + pass + +def config(): + """Get config from the argument parser. + + Return: + bittensor.config object + """ + parser = argparse.ArgumentParser() + add_args(parser) + return bittensor.config(parser, args=[]) + + +logging = LoggingMachine(config()) \ No newline at end of file diff --git a/bittensor/btlogging/defines.py b/bittensor/btlogging/defines.py new file mode 100644 index 0000000000..a51a4c5d25 --- /dev/null +++ b/bittensor/btlogging/defines.py @@ -0,0 +1,7 @@ +BASE_LOG_FORMAT = "%(asctime)s | %(levelname)s | %(message)s" +TRACE_LOG_FORMAT = f"%(asctime)s | %(levelname)s | %(name)s:%(filename)s:%(lineno)s | %(message)s" +DATE_FORMAT = "%Y-%m-%d %H:%M:%S" +BITTENSOR_LOGGER_NAME = "bittensor" +DEFAULT_LOG_FILE_NAME = "bittensor.log" +DEFAULT_MAX_ROTATING_LOG_FILE_SIZE = 25 * 1024 * 1024 +DEFAULT_LOG_BACKUP_COUNT = 10 \ No newline at end of file diff --git a/bittensor/logging/format.py b/bittensor/btlogging/format.py similarity index 95% rename from bittensor/logging/format.py rename to bittensor/btlogging/format.py index a86771a43b..1f7ba6ca88 100644 --- a/bittensor/logging/format.py +++ b/bittensor/btlogging/format.py @@ -7,15 +7,13 @@ Style ) -from bittensor.logging.helpers import get_max_logger_name_length +from bittensor.btlogging.helpers import get_max_logger_name_length init(autoreset=True) - TRACE_LEVELV_NUM = 5 SUCCESS_LEVELV_NUM = 21 - def trace(self, message, *args, **kws): if self.isEnabledFor(TRACE_LEVELV_NUM): self._log(TRACE_LEVELV_NUM, message, args, **kws) @@ -81,7 +79,6 @@ def format(self, record): format_orig = self._style._fmt spacing = get_max_logger_name_length() + 2 record.levelname = f"{record.levelname:^16}" - # record.name = f"{record.name:^28}" if self.trace is True: self._style._fmt = LOG_TRACE_FORMATS[record.levelno] else: diff --git a/bittensor/logging/helpers.py b/bittensor/btlogging/helpers.py similarity index 100% rename from bittensor/logging/helpers.py rename to bittensor/btlogging/helpers.py diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py new file mode 100644 index 0000000000..0d3ec64e6f --- /dev/null +++ b/bittensor/btlogging/loggingmachine.py @@ -0,0 +1,255 @@ +import sys +import logging as stdlogging +from statemachine import StateMachine, State + +from bittensor.btlogging.format import BtStreamFormatter +from bittensor.btlogging.helpers import all_loggers +from bittensor.btlogging.defines import ( + BASE_LOG_FORMAT, + TRACE_LOG_FORMAT, + DATE_FORMAT, + BITTENSOR_LOGGER_NAME, + DEFAULT_LOG_FILE_NAME, + DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, + DEFAULT_LOG_BACKUP_COUNT +) + + +class LoggingMachine(StateMachine): + """ + Handles logger states for bittensor and 3rd party libraries + """ + + Default = State(initial=True) + Debug = State() + Trace = State() + Disabled = State() + + enable_default = ( + Debug.to(Default) + | Trace.to(Default) + | Disabled.to(Default) + | Default.to(Default) + ) + + enable_trace = ( + Default.to(Trace) + | Debug.to(Trace) + | Disabled.to(Trace) + | Trace.to(Trace) + ) + + enable_debug = ( + Default.to(Debug) + | Trace.to(Debug) + | Disabled.to(Debug) + | Debug.to(Debug) + ) + + disable_trace = ( + Trace.to(Default) + ) + + disable_debug = ( + Debug.to(Default) + ) + + disable_logging = ( + Trace.to(Disabled) + | Debug.to(Disabled) + | Default.to(Disabled) + | Disabled.to(Disabled) + ) + + def __init__(self, config: "bittensor.config", name: str=BITTENSOR_LOGGER_NAME): + # set initial state based on config + super(LoggingMachine, self).__init__() + + self._name = name + self._stream_formatter = BtStreamFormatter() + self._file_formatter = stdlogging.Formatter(BASE_LOG_FORMAT, DATE_FORMAT) + + self._logger = self._initialize_bt_logger(name, config) + self._initialize_external_loggers(config) + self.config = config + + # set file handler logic + if config.trace: + self.enable_trace() + elif config.debug: + self.enable_debug() + + def _initialize_bt_logger(self, name, config): + """ + Initialize logging for bittensor. + + Since the initial state is Default, logging level for the module logger + is INFO, and all third-party loggers are silenced. Subsequent state + transitions will handle all logger outputs. + """ + logger = stdlogging.getLogger(name) + + # set stream handler + sh = stdlogging.StreamHandler(sys.stdout) + sh.setFormatter(self._stream_formatter) + logger.addHandler(sh) + logger.setLevel(stdlogging.INFO) + + # set file handler, if applicable + if config.logging_dir and config.record_log: + file_formatter = stdlogging.Formatter(BASE_LOG_FORMAT, DATE_FORMAT) + filepath = os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME) + fh = stdlogging.handlers.RotatingFileHandler( + filepath, + maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, + backupCount=DEFAULT_LOG_BACKUP_COUNT + ) + fh.setFormatter(file_formatter) + logger.addHandler(fh) + + + return logger + + def _initialize_external_loggers(self, config): + # remove all handlers + for logger in all_loggers(): + if logger.name == self._name: + continue + for handler in logger.handlers: + logger.removeHandler(handler) + + # stream handling + sh = stdlogging.StreamHandler(sys.stdout) + sh.setFormatter(self._stream_formatter) + logger.addHandler(sh) + # initial state is default, hence we silence all loggers + logger.setLevel(stdlogging.CRITICAL) + + if config.logging_dir and config.record_log: + # TODO: handle multiple loggers logging to the same file. + pass + # file_formatter = logging.Formatter(BASE_LOG_FORMAT, DATE_FORMAT) + # filepath = os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME) + # fh = logging.handlers.RotatingFileHandler( + # filepath, + # maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, + # backupCount=DEFAULT_LOG_BACKUP_COUNT + # ) + # fh.setFormatter(file_formatter) + # self._logger.addHandler(fh) + + + # state transitions + # Default Logging + def before_enable_default(self): + if self.current_state_value == "Default": + return + self._logger.setLevel(stdlogging.INFO) + self._stream_formatter.set_trace(False) + for logger in all_loggers(): + if logger.name == self._name: + continue + logger.setLevel(stdlogging.CRITICAL) + + def after_enable_default(self): + pass + + # Trace + def before_enable_trace(self): + if self.current_state_value == "Trace": + return + self._logger.info("Enabling trace.") + self._stream_formatter.set_trace(True) + for logger in all_loggers(): + logger.setLevel(stdlogging.TRACE) + + def after_enable_trace(self): + self._logger.info("Trace enabled.") + + def before_disable_trace(self): + self._logger.info("Disabling trace.") + self._stream_formatter.set_trace(False) + self.enable_default() + + def after_disable_trace(self): + self._logger.info("Trace disabled.") + + # Debug + def before_enable_debug(self): + if self.current_state_value == "Debug": + return + self._logger.info("Enabling debug.") + self._stream_formatter.set_trace(True) + for logger in all_loggers(): + logger.setLevel(stdlogging.DEBUG) + + def after_enable_debug(self): + self._logger.info("Debug enabled.") + + def before_disable_debug(self): + self._logger.info("Disabling debug.") + self._stream_formatter.set_trace(False) + self.enable_default() + + def after_disable_debug(self): + self._logger.info("Debug disabled.") + + # Disable Logging + def before_disable_logging(self): + self._logger.info("Disabling logging.") + self._stream_formatter.set_trace(False) + for logger in all_loggers(): + logger.setLevel(stdlogging.CRITICAL) + + # Required API + # support log commands for API backwards compatibility + def trace(self, msg, *args, **kwargs): + self._logger.trace(msg, *args, **kwargs) + + def debug(self, msg, *args, **kwargs): + self._logger.debug(msg, *args, **kwargs) + + def info(self, msg, *args, **kwargs): + self._logger.info(msg, *args, **kwargs) + + def success(self, msg, *args, **kwargs): + self._logger.success(msg, *args, **kwargs) + + def warning(self, msg, *args, **kwargs): + self._logger.warning(msg, *args, **kwargs) + + def error(self, msg, *args, **kwargs): + self._logger.error(msg, *args, **kwargs) + + def critical(self, msg, *args, **kwargs): + self._logger.critical(msg, *args, **kwargs) + + def exception(self, msg, *args, **kwargs): + self._logger.exception(msg, *args, **kwargs) + + def on(self): + self.enable_default() + + def off(self): + self.disable_logging() + + def set_debug(self, on: bool=True): + if on: + self.enable_debug() + else: + if self.current_state_value == "Debug": + self.disable_debug() + + + def set_trace(self, on: bool=True): + if on: + self.enable_trace() + else: + if self.current_state_value == "Trace": + self.disable_trace() + + def get_level(self): + return self._logger.level + + def help(self): + pass \ No newline at end of file diff --git a/bittensor/logging/__init__.py b/bittensor/logging/__init__.py deleted file mode 100644 index a21c5df1a3..0000000000 --- a/bittensor/logging/__init__.py +++ /dev/null @@ -1,216 +0,0 @@ -import os -import sys -import time -import logging -import argparse -from typing import Optional, NamedTuple - -import bittensor.config -from bittensor.logging.format import BtStreamFormatter -from bittensor.logging.helpers import all_loggers - - -BASE_LOG_FORMAT = "%(asctime)s | %(levelname)s | %(message)s" -DATE_FORMAT = "%Y-%m-%d %H:%M:%S" -BITTENSOR_LOGGER_NAME = "bittensor" - - -class LoggingConfig(NamedTuple): - debug: bool - trace: bool - logging_dir: str - record_log: bool - - -def __enable_logger_and_set_bt_format( - logger: logging.Logger, - log_level: int=logging.INFO, - logfile: str="bittensor.log" -): - handler = logging.StreamHandler(stream=sys.stdout) - handler.setFormatter(BtStreamFormatter(BASE_LOG_FORMAT, DATE_FORMAT)) - handler.setLevel(log_level) - handler.formatter.set_trace(True) - - logger.addHandler(handler) - logger.setLevel(log_level) - - -def getLogger(name: str = BITTENSOR_LOGGER_NAME): - logger = logging.getLogger(name) - for handler in logger.handlers[:]: - if isinstance(handler, logging.StreamHandler): - logger.removeHandler(handler) - - handler = logging.StreamHandler(stream=sys.stdout) - handler.setLevel(logging.INFO) - handler.setFormatter(BtStreamFormatter(BASE_LOG_FORMAT, DATE_FORMAT)) - logger.addHandler(handler) - logger.setLevel(logging.INFO) - - return logger - - -def set_trace(on: bool=True): - bt_logger = logging.getLogger(BITTENSOR_LOGGER_NAME) - if on: - for logger in all_loggers(): - __enable_logger_and_set_bt_format(logger, log_level=logging.TRACE) - else: - __set_default_logging(bt_logger) - for logger in all_loggers(): - if logger.name is BITTENSOR_LOGGER_NAME: - __set_default_logging(logger) - __disable_logger(logger) - - -def set_debug(on: bool=True): - if on: - for logger in all_loggers(): - __enable_logger(level=logging.DEBUG) - else: - for logger in all_loggers(): - if logger.name is BITTENSOR_LOGGER_NAME: - __set_default_logging(logger) - __disable_logger(logger) - - -def __disable_logger(logger: logging.Logger): - logger.setLevel(logging.CRITICAL) - for handler in logger.handlers: - if isinstance(handler.formatter, BtStreamFormatter): - handler.formatter.set_trace(False) - else: - logger.removeHandler(handler) - - -def __enable_debug(logger: logging.Logger): - pass - - -def __set_default_logging_global(): - for logger in all_loggers(): - if logger.name == BITTENSOR_LOGGER_NAME: - __set_default_logging(logger) - else: - __disable_logger(logger) - - -def __disable_third_party_loggers(): - for logger in all_loggers(): - if logger.name == BITTENSOR_LOGGER_NAME: - continue - __disable_logger(logger) - - -def __set_default_logging(logger: logging.Logger): - logger.setLevel(logging.INFO) - for handler in logger.handlers: - if isinstance(handler.formatter, BtStreamFormatter): - handler.setLevel(logging.INFO) - handler.formatter.set_trace(False) - - -def on(): - logger = logging.getLogger(BITTENSOR_LOGGER_NAME) - __enable_logger_and_set_bt_format(logger, logging.INFO) - - -def off(): - for logger in all_loggers(): - __disable_logger(logger) - - -def add_args(cls, parser: argparse.ArgumentParser, prefix: str = None): - """Accept specific arguments fro parser""" - prefix_str = "" if prefix == None else prefix + "." - try: - default_logging_debug = os.getenv("BT_LOGGING_DEBUG") or False - default_logging_trace = os.getenv("BT_LOGGING_TRACE") or False - default_logging_record_log = os.getenv("BT_LOGGING_RECORD_LOG") or False - default_logging_logging_dir = ( - os.getenv("BT_LOGGING_LOGGING_DIR") or "~/.bittensor/miners" - ) - parser.add_argument( - "--" + prefix_str + "logging.debug", - action="store_true", - help="""Turn on bittensor debugging information""", - default=default_logging_debug, - ) - parser.add_argument( - "--" + prefix_str + "logging.trace", - action="store_true", - help="""Turn on bittensor trace level information""", - default=default_logging_trace, - ) - parser.add_argument( - "--" + prefix_str + "logging.record_log", - action="store_true", - help="""Turns on logging to file.""", - default=default_logging_record_log, - ) - parser.add_argument( - "--" + prefix_str + "logging.logging_dir", - type=str, - help="Logging default root directory.", - default=default_logging_logging_dir, - ) - except argparse.ArgumentError: - # re-parsing arguments. - pass - - -def config(cls): - """Get config from the argument parser. - - Return: - bittensor.config object - """ - parser = argparse.ArgumentParser() - add_args(parser) - return bittensor.config(parser, args=[]) - - - -logger = getLogger(BITTENSOR_LOGGER_NAME) - - -# class btlogging: -# @classmethod -# def on(cls): -# """Turn on logging output by re-adding the sinks.""" -# if cls.__off__: -# cls.__off__ = False - -# cls.__std_sink__ = logging.StreamHandler( -# sys.stdout, -# colorize=True, -# enqueue=True, -# backtrace=True, -# diagnose=True, -# format=cls.log_formatter, -# ) -# cls.__std_sink__.setLevel(logging.NOTSET) - -# logger.addHandler(cls.__std_sink__) - -# # Check if logging to file was originally enabled and re-add the file sink -# if cls.__file_sink__ is not None: -# config = cls.config() -# filepath = config.logging.logging_dir + "/logs.log" -# cls.__file_sink__ = logging.FileHandler( -# filepath, -# enqueue=True, -# backtrace=True, -# diagnose=True, -# format=cls.log_save_formatter, -# rotation="25 MB", -# retention="10 days", -# ) -# logging.addHandler(cls.__file_sink__) - -# cls.set_debug(cls.__debug_on__) -# cls.set_trace(cls.__trace_on__) - - - diff --git a/bittensor/logging/logging.md b/bittensor/logging/logging.md deleted file mode 100644 index 0470c5f5bb..0000000000 --- a/bittensor/logging/logging.md +++ /dev/null @@ -1,5 +0,0 @@ -# Sequence Diagram - -```mermaid - -``` \ No newline at end of file From 9d7bbbef957e9ffa830a1cbbb8dbd4a91af96feb Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 14 Mar 2024 23:56:10 -0400 Subject: [PATCH 11/33] Replace loguru with builtin logger --- bittensor/btlogging/loggingmachine.py | 4 +++- bittensor/extrinsics/delegation.py | 6 +++--- bittensor/extrinsics/root.py | 8 ++++---- bittensor/extrinsics/set_weights.py | 6 +++--- bittensor/subtensor.py | 5 +++-- bittensor/threadpool.py | 6 +++++- requirements/prod.txt | 3 ++- scripts/environments/apple_m1_environment.yml | 3 ++- 8 files changed, 25 insertions(+), 16 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 0d3ec64e6f..ca6e62606b 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -137,7 +137,9 @@ def _initialize_external_loggers(self, config): # ) # fh.setFormatter(file_formatter) # self._logger.addHandler(fh) - + + def get_logger(self, name: str) -> stdlogging.Logger: + return self._logger # state transitions # Default Logging diff --git a/bittensor/extrinsics/delegation.py b/bittensor/extrinsics/delegation.py index 5a631b0528..0b3bdb7d64 100644 --- a/bittensor/extrinsics/delegation.py +++ b/bittensor/extrinsics/delegation.py @@ -16,15 +16,15 @@ # OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER # DEALINGS IN THE SOFTWARE. +import logging import bittensor from ..errors import NominationError, NotDelegateError, NotRegisteredError, StakeError from rich.prompt import Confirm from typing import Union, Optional from bittensor.utils.balance import Balance +from bittensor.btlogging.defines import BITTENSOR_LOGGER_NAME -from loguru import logger - -logger = logger.opt(colors=True) +logger = logging.getLogger(BITTENSOR_LOGGER_NAME) def nominate_extrinsic( diff --git a/bittensor/extrinsics/root.py b/bittensor/extrinsics/root.py index d0eb035dd9..ab8b314870 100644 --- a/bittensor/extrinsics/root.py +++ b/bittensor/extrinsics/root.py @@ -20,13 +20,13 @@ import time import torch +import logging from rich.prompt import Confirm from typing import Union import bittensor.utils.weight_utils as weight_utils +from bittensor.btlogging.defines import BITTENSOR_LOGGER_NAME -from loguru import logger - -logger = logger.opt(colors=True) +logger = logging.getLogger(BITTENSOR_LOGGER_NAME) def root_register_extrinsic( @@ -211,7 +211,7 @@ def set_root_weights_extrinsic( return False except Exception as e: - # TODO( devs ): lets remove all of the bittensor.__console__ calls and replace with loguru. + # TODO( devs ): lets remove all of the bittensor.__console__ calls and replace with the bittensor logger. bittensor.__console__.print( ":cross_mark: [red]Failed[/red]: error:{}".format(e) ) diff --git a/bittensor/extrinsics/set_weights.py b/bittensor/extrinsics/set_weights.py index 1ba97fdc9d..5e0c7cc6af 100644 --- a/bittensor/extrinsics/set_weights.py +++ b/bittensor/extrinsics/set_weights.py @@ -19,13 +19,13 @@ import bittensor import torch +import logging from rich.prompt import Confirm from typing import Union, Tuple import bittensor.utils.weight_utils as weight_utils +from bittensor.btlogging.defines import BITTENSOR_LOGGER_NAME -from loguru import logger - -logger = logger.opt(colors=True) +logger = logging.getLogger(BITTENSOR_LOGGER_NAME) def set_weights_extrinsic( diff --git a/bittensor/subtensor.py b/bittensor/subtensor.py index 4d80260d09..afbbf938de 100644 --- a/bittensor/subtensor.py +++ b/bittensor/subtensor.py @@ -20,12 +20,12 @@ import copy import time import torch +import logging import argparse import bittensor import scalecodec from retry import retry -from loguru import logger from typing import List, Dict, Union, Optional, Tuple, TypedDict, Any, TypeVar from substrateinterface.base import QueryMapResult, SubstrateInterface, ExtrinsicReceipt from substrateinterface.exceptions import SubstrateRequestException @@ -34,6 +34,7 @@ from scalecodec.types import GenericCall # Local imports. +from .btlogging.defines import BITTENSOR_LOGGER_NAME from .chain_data import ( NeuronInfo, DelegateInfo, @@ -85,7 +86,7 @@ from .utils.balance import Balance from .utils.registration import POWSolution -logger = logger.opt(colors=True) +logger = logging.getLogger(BITTENSOR_LOGGER_NAME) KEY_NONCE: Dict[str, int] = {} diff --git a/bittensor/threadpool.py b/bittensor/threadpool.py index 2211331453..c20d64a6b3 100644 --- a/bittensor/threadpool.py +++ b/bittensor/threadpool.py @@ -11,15 +11,17 @@ import queue import random import weakref +import logging import argparse import bittensor import itertools import threading -from loguru import logger from typing import Callable from concurrent.futures import _base +from bittensor.btlogging.defines import BITTENSOR_LOGGER_NAME + # Workers are created as daemon threads. This is done to allow the interpreter # to exit when there are still idle threads in a ThreadPoolExecutor's thread # pool (i.e. shutdown() was not called). However, allowing workers to die with @@ -34,6 +36,8 @@ # workers to exit when their work queues are empty and then waits until the # threads finish. +logger = logging.getLogger(BITTENSOR_LOGGER_NAME) + _threads_queues = weakref.WeakKeyDictionary() _shutdown = False diff --git a/requirements/prod.txt b/requirements/prod.txt index cf1a6ba7ad..2ab6b1cbf6 100644 --- a/requirements/prod.txt +++ b/requirements/prod.txt @@ -3,11 +3,11 @@ ansible==6.7.0 ansible_vault==2.1.0 backoff black==23.7.0 +colorama==0.4.6 cryptography==42.0.0 ddt==1.6.0 fuzzywuzzy>=0.18.0 fastapi==0.99.1 -loguru==0.7.0 munch==2.5.0 netaddr numpy @@ -20,6 +20,7 @@ pydantic!=1.8,!=1.8.1,<2.0.0,>=1.7.4 PyNaCl>=1.3.0,<=1.5.0 pytest-asyncio python-Levenshtein +python-statemachine==2.1.2 pytest retry requests diff --git a/scripts/environments/apple_m1_environment.yml b/scripts/environments/apple_m1_environment.yml index 3c2c6a5826..f1ca820fba 100644 --- a/scripts/environments/apple_m1_environment.yml +++ b/scripts/environments/apple_m1_environment.yml @@ -134,6 +134,7 @@ dependencies: - cfgv==3.4.0 - chardet==3.0.4 - click==8.1.3 + - colorama==0.4.6 - commonmark==0.9.1 - cryptography==41.0.3 - cytoolz==0.12.2 @@ -176,7 +177,6 @@ dependencies: - jupyter==1.0.0 - jupyter-console==6.6.3 - jupyterlab-widgets==3.0.7 - - loguru==0.7.0 - markupsafe==2.0.1 - marshmallow==3.19.0 - marshmallow-enum==1.5.1 @@ -217,6 +217,7 @@ dependencies: - pympler==1.0.1 - pynacl==1.5.0 - pyparsing==3.1.1 + - python-statemachine==2.1.2 - pytest==7.4.0 - qqdm==0.0.7 - qtconsole==5.4.3 From ac91a40a566b210993adb79a1eb6cea1c394c23f Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 14 Mar 2024 23:58:53 -0400 Subject: [PATCH 12/33] Clean up. Removed some commented code that will be replaced anyway. --- bittensor/btlogging/loggingmachine.py | 12 ------------ 1 file changed, 12 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index ca6e62606b..ebcc3d5934 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -128,18 +128,6 @@ def _initialize_external_loggers(self, config): if config.logging_dir and config.record_log: # TODO: handle multiple loggers logging to the same file. pass - # file_formatter = logging.Formatter(BASE_LOG_FORMAT, DATE_FORMAT) - # filepath = os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME) - # fh = logging.handlers.RotatingFileHandler( - # filepath, - # maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, - # backupCount=DEFAULT_LOG_BACKUP_COUNT - # ) - # fh.setFormatter(file_formatter) - # self._logger.addHandler(fh) - - def get_logger(self, name: str) -> stdlogging.Logger: - return self._logger # state transitions # Default Logging From bc68180c378fd6dac3f230c5afed6b06ddd670df Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Mon, 18 Mar 2024 12:04:03 -0400 Subject: [PATCH 13/33] Add support for multiprocessing logging with queue. In order to capture logs from processes, a QueueHandler must be added to the logger that is instantiated with the LoggingMachine queue. The file log, if enabled, uses the trace format output for all loggers regardless of higher level settings. This is to avoid modifying the formatter during program execution. --- bittensor/__init__.py | 2 +- bittensor/btlogging/loggingmachine.py | 93 ++++++++++++++++++--------- tests/unit_tests/test_logging.py | 4 +- 3 files changed, 66 insertions(+), 33 deletions(-) diff --git a/bittensor/__init__.py b/bittensor/__init__.py index 5105141b68..1d2b506f85 100644 --- a/bittensor/__init__.py +++ b/bittensor/__init__.py @@ -309,6 +309,6 @@ def debug(on: bool = True): subtensor.config(), PriorityThreadPoolExecutor.config(), wallet.config(), - logging.config, + logging.get_config(), ] defaults = config.merge_all(configs) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index ebcc3d5934..51e8f9c499 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -1,5 +1,9 @@ +import os import sys +import atexit import logging as stdlogging +import multiprocessing as mp +from typing import NamedTuple from statemachine import StateMachine, State from bittensor.btlogging.format import BtStreamFormatter @@ -15,6 +19,13 @@ ) +class LoggingConfig(NamedTuple): + debug: bool + trace: bool + record_log: bool + logging_dir: str + + class LoggingMachine(StateMachine): """ Handles logger states for bittensor and 3rd party libraries @@ -67,18 +78,43 @@ def __init__(self, config: "bittensor.config", name: str=BITTENSOR_LOGGER_NAME): self._name = name self._stream_formatter = BtStreamFormatter() - self._file_formatter = stdlogging.Formatter(BASE_LOG_FORMAT, DATE_FORMAT) + self._file_formatter = stdlogging.Formatter(TRACE_LOG_FORMAT, DATE_FORMAT) self._logger = self._initialize_bt_logger(name, config) self._initialize_external_loggers(config) - self.config = config + self.set_config(config) + + def get_config(self): + return self._config - # set file handler logic + def set_config(self, config): + self._config = config + if config.logging_dir and config.record_log: + logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) + self.info(f"Enabling file logging to: {logfile}") + self._enable_file_logging(logfile) if config.trace: self.enable_trace() elif config.debug: self.enable_debug() - + + def _create_file_listener(self, logfile: str): + self._queue = mp.Queue(-1) + self._file_handler = stdlogging.handlers.RotatingFileHandler( + logfile, + maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, + backupCount=DEFAULT_LOG_BACKUP_COUNT + ) + self._file_handler.setFormatter(self._file_formatter) + listener = stdlogging.handlers.QueueListener(self._queue, self._file_handler, respect_handler_level=True) + return listener + + def get_queue(self): + if hasattr(self, "_queue"): + return self._queue + else: + raise AttributeError("File logging is not enabled, no queue available.") + def _initialize_bt_logger(self, name, config): """ Initialize logging for bittensor. @@ -94,19 +130,6 @@ def _initialize_bt_logger(self, name, config): sh.setFormatter(self._stream_formatter) logger.addHandler(sh) logger.setLevel(stdlogging.INFO) - - # set file handler, if applicable - if config.logging_dir and config.record_log: - file_formatter = stdlogging.Formatter(BASE_LOG_FORMAT, DATE_FORMAT) - filepath = os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME) - fh = stdlogging.handlers.RotatingFileHandler( - filepath, - maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, - backupCount=DEFAULT_LOG_BACKUP_COUNT - ) - fh.setFormatter(file_formatter) - logger.addHandler(fh) - return logger @@ -126,14 +149,22 @@ def _initialize_external_loggers(self, config): logger.setLevel(stdlogging.CRITICAL) if config.logging_dir and config.record_log: - # TODO: handle multiple loggers logging to the same file. - pass + queue_handler = stdlogging.handlers.QueueHandler(self._queue) + logger.addHandler(queue_handler) + + def _enable_file_logging(self, logfile:str): + self._listener = self._create_file_listener(logfile) + atexit.register(self._listener.stop) + self._listener.start() + queue_handler = stdlogging.handlers.QueueHandler(self._queue) + + for logger in all_loggers(): + logger.addHandler(queue_handler) # state transitions # Default Logging def before_enable_default(self): - if self.current_state_value == "Default": - return + self._logger.info(f"Enabling default logging.") self._logger.setLevel(stdlogging.INFO) self._stream_formatter.set_trace(False) for logger in all_loggers(): @@ -143,11 +174,14 @@ def before_enable_default(self): def after_enable_default(self): pass + + + def __del__(self): + self._listener.stop() + super().__del__() # Trace def before_enable_trace(self): - if self.current_state_value == "Trace": - return self._logger.info("Enabling trace.") self._stream_formatter.set_trace(True) for logger in all_loggers(): @@ -157,7 +191,7 @@ def after_enable_trace(self): self._logger.info("Trace enabled.") def before_disable_trace(self): - self._logger.info("Disabling trace.") + self._logger.info(f"Disabling trace.") self._stream_formatter.set_trace(False) self.enable_default() @@ -166,8 +200,6 @@ def after_disable_trace(self): # Debug def before_enable_debug(self): - if self.current_state_value == "Debug": - return self._logger.info("Enabling debug.") self._stream_formatter.set_trace(True) for logger in all_loggers(): @@ -218,23 +250,24 @@ def exception(self, msg, *args, **kwargs): self._logger.exception(msg, *args, **kwargs) def on(self): + self._logger.info("Logging enabled.") self.enable_default() def off(self): self.disable_logging() def set_debug(self, on: bool=True): - if on: + if on and not self.current_state_value == "Debug": self.enable_debug() - else: + elif not on: if self.current_state_value == "Debug": self.disable_debug() def set_trace(self, on: bool=True): - if on: + if on and not self.current_state_value == "Trace": self.enable_trace() - else: + elif not on: if self.current_state_value == "Trace": self.disable_trace() diff --git a/tests/unit_tests/test_logging.py b/tests/unit_tests/test_logging.py index 7a740f02ba..696684a267 100644 --- a/tests/unit_tests/test_logging.py +++ b/tests/unit_tests/test_logging.py @@ -1,7 +1,7 @@ import logging import pytest -from bittensor.logging import ( +from bittensor.btlogging import ( getLogger, trace, __enable_non_bt_loggers, @@ -12,7 +12,7 @@ __set_bt_format_logger, BITTENSOR_LOGGER_NAME ) -from bittensor.logging.format import BtStreamFormatter +from bittensor.btlogging.format import BtStreamFormatter # Mock for all_loggers function From 26805902a5b67fb285b34faf9a6e48f081f4b525 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Tue, 19 Mar 2024 13:02:37 -0400 Subject: [PATCH 14/33] Refactor LoggingMachine to ingest purely from a queue. To enable stdout streaming of external process loggers within the main process, all log record handling has been moved to a single QueueListener owned by the LoggingMachine. This way, handlers can be added or removed as necessary. To ensure that state transitions are respected temporally, as the QueueListener operates in a separate thread, a Lock was added to control operations on anything related to the QueueListener. --- bittensor/__init__.py | 1 - bittensor/btlogging/format.py | 20 +++- bittensor/btlogging/loggingmachine.py | 166 ++++++++++++++++---------- 3 files changed, 118 insertions(+), 69 deletions(-) diff --git a/bittensor/__init__.py b/bittensor/__init__.py index 1d2b506f85..63fd4b60b8 100644 --- a/bittensor/__init__.py +++ b/bittensor/__init__.py @@ -288,7 +288,6 @@ def debug(on: bool = True): from .subtensor import subtensor as subtensor from .cli import cli as cli, COMMANDS as ALL_COMMANDS from .btlogging import logging -# from .logging import LoggingMachine, from .metagraph import metagraph as metagraph from .threadpool import PriorityThreadPoolExecutor as PriorityThreadPoolExecutor diff --git a/bittensor/btlogging/format.py b/bittensor/btlogging/format.py index 1f7ba6ca88..ca5eeb0e79 100644 --- a/bittensor/btlogging/format.py +++ b/bittensor/btlogging/format.py @@ -77,7 +77,6 @@ def format(self, record): # Save the original format configured by the user # when the logger formatter was instantiated format_orig = self._style._fmt - spacing = get_max_logger_name_length() + 2 record.levelname = f"{record.levelname:^16}" if self.trace is True: self._style._fmt = LOG_TRACE_FORMATS[record.levelno] @@ -89,5 +88,22 @@ def format(self, record): return result def set_trace(self, state: bool = True): + self.trace = state - self.trace = state \ No newline at end of file +class BtFileFormatter(logging.Formatter): + def formatTime(self, record, datefmt=None): + """ + Override formatTime to add milliseconds. + """ + created = self.converter(record.created) + if datefmt: + s = time.strftime(datefmt, created) + else: + s = time.strftime("%Y-%m-%d %H:%M:%S", created) + s += ".{:03d}".format(int(record.msecs)) + return s + + def format(self, record): + record.levelname = f"{record.levelname:^16}" + record.name + return super().format(record) \ No newline at end of file diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 51e8f9c499..b2335c8d18 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -1,12 +1,14 @@ import os import sys import atexit -import logging as stdlogging +import threading import multiprocessing as mp +import logging as stdlogging from typing import NamedTuple from statemachine import StateMachine, State +from logging.handlers import QueueHandler, QueueListener, RotatingFileHandler -from bittensor.btlogging.format import BtStreamFormatter +from bittensor.btlogging.format import BtStreamFormatter, BtFileFormatter from bittensor.btlogging.helpers import all_loggers from bittensor.btlogging.defines import ( BASE_LOG_FORMAT, @@ -76,13 +78,24 @@ def __init__(self, config: "bittensor.config", name: str=BITTENSOR_LOGGER_NAME): # set initial state based on config super(LoggingMachine, self).__init__() + # basics + self._queue = mp.Queue(-1) # all self._name = name + self._lock = threading.Lock() + + # handlers + # TODO: change this to a list of handlers, so that self.listener.handlers + # can be updated to modify sinks + # self._handlers = list() + self._stream_formatter = BtStreamFormatter() - self._file_formatter = stdlogging.Formatter(TRACE_LOG_FORMAT, DATE_FORMAT) + self._file_formatter = BtFileFormatter(TRACE_LOG_FORMAT, DATE_FORMAT) + + self.set_config(config) self._logger = self._initialize_bt_logger(name, config) self._initialize_external_loggers(config) - self.set_config(config) + def get_config(self): return self._config @@ -98,15 +111,19 @@ def set_config(self, config): elif config.debug: self.enable_debug() - def _create_file_listener(self, logfile: str): - self._queue = mp.Queue(-1) - self._file_handler = stdlogging.handlers.RotatingFileHandler( - logfile, - maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, - backupCount=DEFAULT_LOG_BACKUP_COUNT - ) - self._file_handler.setFormatter(self._file_formatter) - listener = stdlogging.handlers.QueueListener(self._queue, self._file_handler, respect_handler_level=True) + def _create_listener(self, handlers): + """ + A listener to receive and publish log records. + + This listener receives records from a queue populated by the main bittensor + logger, as well as 3rd party loggers. The output sinks + """ + + listener = QueueListener( + self._queue, + *handlers, + respect_handler_level=True + ) return listener def get_queue(self): @@ -124,15 +141,35 @@ def _initialize_bt_logger(self, name, config): transitions will handle all logger outputs. """ logger = stdlogging.getLogger(name) + queue_handler = QueueHandler(self._queue) + logger.addHandler(queue_handler) + handlers = list() - # set stream handler - sh = stdlogging.StreamHandler(sys.stdout) - sh.setFormatter(self._stream_formatter) - logger.addHandler(sh) - logger.setLevel(stdlogging.INFO) + # main handler + stream_handler = stdlogging.StreamHandler(sys.stdout) + stream_handler.setFormatter(self._stream_formatter) + handlers.append(stream_handler) + + if config.record_log and config.logging_dir: + logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) + handlers.append(self._create_file_handler(logfile)) + + self._handlers = handlers + self._listener = self._create_listener(handlers) + self._listener.start() + atexit.register(self._listener.stop) return logger + def _create_file_handler(self, logfile: str): + file_handler = RotatingFileHandler( + logfile, + maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, + backupCount=DEFAULT_LOG_BACKUP_COUNT + ) + file_handler.setFormatter(self._file_formatter) + return file_handler + def _initialize_external_loggers(self, config): # remove all handlers for logger in all_loggers(): @@ -140,88 +177,85 @@ def _initialize_external_loggers(self, config): continue for handler in logger.handlers: logger.removeHandler(handler) - - # stream handling - sh = stdlogging.StreamHandler(sys.stdout) - sh.setFormatter(self._stream_formatter) - logger.addHandler(sh) - # initial state is default, hence we silence all loggers - logger.setLevel(stdlogging.CRITICAL) - - if config.logging_dir and config.record_log: - queue_handler = stdlogging.handlers.QueueHandler(self._queue) - logger.addHandler(queue_handler) + for handler in self._handlers: + logger.addHandler(handler) + logger.setLevel(stdlogging.CRITICAL) def _enable_file_logging(self, logfile:str): - self._listener = self._create_file_listener(logfile) - atexit.register(self._listener.stop) - self._listener.start() - queue_handler = stdlogging.handlers.QueueHandler(self._queue) - - for logger in all_loggers(): - logger.addHandler(queue_handler) + # preserve idempotency; do not create extra filehandlers + # if one already exists + if any([isinstance(handler, RotatingFileHandler) for handler in self._handlers]): + return + with self._lock: + file_handler = self._create_file_handler(logfile) + self._handlers.append(file_handler) + self._listener.handlers = tuple(self._handlers) + + for logger in all_loggers(): + logger.addHandler(file_handler) # state transitions # Default Logging def before_enable_default(self): - self._logger.info(f"Enabling default logging.") - self._logger.setLevel(stdlogging.INFO) - self._stream_formatter.set_trace(False) - for logger in all_loggers(): - if logger.name == self._name: - continue - logger.setLevel(stdlogging.CRITICAL) + with self._lock: + self._logger.info(f"Enabling default logging.") + self._logger.setLevel(stdlogging.INFO) + self._stream_formatter.set_trace(False) + for logger in all_loggers(): + if logger.name == self._name: + continue + logger.setLevel(stdlogging.CRITICAL) def after_enable_default(self): pass - - def __del__(self): - self._listener.stop() - super().__del__() - # Trace def before_enable_trace(self): - self._logger.info("Enabling trace.") - self._stream_formatter.set_trace(True) - for logger in all_loggers(): - logger.setLevel(stdlogging.TRACE) + with self._lock: + self._logger.info("Enabling trace.") + self._stream_formatter.set_trace(True) + for logger in all_loggers(): + logger.setLevel(stdlogging.TRACE) def after_enable_trace(self): self._logger.info("Trace enabled.") def before_disable_trace(self): - self._logger.info(f"Disabling trace.") - self._stream_formatter.set_trace(False) - self.enable_default() + with self._lock: + self._logger.info(f"Disabling trace.") + self._stream_formatter.set_trace(False) + self.enable_default() def after_disable_trace(self): self._logger.info("Trace disabled.") # Debug def before_enable_debug(self): - self._logger.info("Enabling debug.") - self._stream_formatter.set_trace(True) - for logger in all_loggers(): - logger.setLevel(stdlogging.DEBUG) + with self._lock: + self._logger.info("Enabling debug.") + self._stream_formatter.set_trace(True) + for logger in all_loggers(): + logger.setLevel(stdlogging.DEBUG) def after_enable_debug(self): self._logger.info("Debug enabled.") def before_disable_debug(self): - self._logger.info("Disabling debug.") - self._stream_formatter.set_trace(False) - self.enable_default() + with self._lock: + self._logger.info("Disabling debug.") + self._stream_formatter.set_trace(False) + self.enable_default() def after_disable_debug(self): self._logger.info("Debug disabled.") # Disable Logging def before_disable_logging(self): - self._logger.info("Disabling logging.") - self._stream_formatter.set_trace(False) - for logger in all_loggers(): - logger.setLevel(stdlogging.CRITICAL) + with self._lock: + self._logger.info("Disabling logging.") + self._stream_formatter.set_trace(False) + for logger in all_loggers(): + logger.setLevel(stdlogging.CRITICAL) # Required API # support log commands for API backwards compatibility From 9fae1c9af804a3c0fdf03a2e511ec9640edc5129 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Tue, 19 Mar 2024 17:07:04 -0400 Subject: [PATCH 15/33] Partial implementation of syncronization of logger state and log emission --- bittensor/btlogging/format.py | 25 +++++--- bittensor/btlogging/loggingmachine.py | 83 ++++++++++++++------------- 2 files changed, 60 insertions(+), 48 deletions(-) diff --git a/bittensor/btlogging/format.py b/bittensor/btlogging/format.py index ca5eeb0e79..801db421a8 100644 --- a/bittensor/btlogging/format.py +++ b/bittensor/btlogging/format.py @@ -1,5 +1,7 @@ +import os import time import logging +import threading from colorama import ( init, Fore, @@ -59,7 +61,11 @@ def success(self, message, *args, **kws): class BtStreamFormatter(logging.Formatter): - trace = False + + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + self.trace = False + self.lock = threading.Lock() def formatTime(self, record, datefmt=None): """ @@ -78,17 +84,23 @@ def format(self, record): # when the logger formatter was instantiated format_orig = self._style._fmt record.levelname = f"{record.levelname:^16}" - if self.trace is True: - self._style._fmt = LOG_TRACE_FORMATS[record.levelno] - else: - self._style._fmt = LOG_FORMATS[record.levelno] + with self.lock: + if self.trace is True: + self._style._fmt = LOG_TRACE_FORMATS[record.levelno] + else: + self._style._fmt = LOG_FORMATS[record.levelno] + result = super().format(record) self._style._fmt = format_orig return result def set_trace(self, state: bool = True): - self.trace = state + print(f"setting trace: {state}") + with self.lock: + print(f"lock acquired...") + self.trace = state + print(f"trace set to {state}") class BtFileFormatter(logging.Formatter): def formatTime(self, record, datefmt=None): @@ -105,5 +117,4 @@ def formatTime(self, record, datefmt=None): def format(self, record): record.levelname = f"{record.levelname:^16}" - record.name return super().format(record) \ No newline at end of file diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index b2335c8d18..efbc511c69 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -151,8 +151,9 @@ def _initialize_bt_logger(self, name, config): handlers.append(stream_handler) if config.record_log and config.logging_dir: - logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) - handlers.append(self._create_file_handler(logfile)) + # logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) + # handlers.append(self._create_file_handler(logfile)) + pass self._handlers = handlers self._listener = self._create_listener(handlers) @@ -168,6 +169,7 @@ def _create_file_handler(self, logfile: str): backupCount=DEFAULT_LOG_BACKUP_COUNT ) file_handler.setFormatter(self._file_formatter) + file_handler.setLevel(stdlogging.TRACE) return file_handler def _initialize_external_loggers(self, config): @@ -177,85 +179,84 @@ def _initialize_external_loggers(self, config): continue for handler in logger.handlers: logger.removeHandler(handler) - for handler in self._handlers: - logger.addHandler(handler) + queue_handler = QueueHandler(self._queue) + logger.addHandler(queue_handler) logger.setLevel(stdlogging.CRITICAL) def _enable_file_logging(self, logfile:str): # preserve idempotency; do not create extra filehandlers # if one already exists - if any([isinstance(handler, RotatingFileHandler) for handler in self._handlers]): - return + # if any([isinstance(handler, RotatingFileHandler) for handler in self._handlers]): + # return with self._lock: file_handler = self._create_file_handler(logfile) self._handlers.append(file_handler) + self._listener.stop() self._listener.handlers = tuple(self._handlers) - - for logger in all_loggers(): - logger.addHandler(file_handler) + self._listener.start() # state transitions # Default Logging def before_enable_default(self): - with self._lock: - self._logger.info(f"Enabling default logging.") - self._logger.setLevel(stdlogging.INFO) - self._stream_formatter.set_trace(False) - for logger in all_loggers(): - if logger.name == self._name: - continue - logger.setLevel(stdlogging.CRITICAL) + # with self._lock: + self._logger.info(f"Enabling default logging.") + self._logger.setLevel(stdlogging.INFO) + self._stream_formatter.set_trace(False) + for logger in all_loggers(): + if logger.name == self._name: + continue + logger.setLevel(stdlogging.CRITICAL) def after_enable_default(self): pass # Trace def before_enable_trace(self): - with self._lock: - self._logger.info("Enabling trace.") - self._stream_formatter.set_trace(True) - for logger in all_loggers(): - logger.setLevel(stdlogging.TRACE) + # with self._lock: + self._logger.info("Enabling trace.") + self._stream_formatter.set_trace(True) + for logger in all_loggers(): + logger.setLevel(stdlogging.TRACE) def after_enable_trace(self): self._logger.info("Trace enabled.") def before_disable_trace(self): - with self._lock: - self._logger.info(f"Disabling trace.") - self._stream_formatter.set_trace(False) - self.enable_default() + # with self._lock: + self._logger.info(f"Disabling trace.") + self._stream_formatter.set_trace(False) + self.enable_default() def after_disable_trace(self): self._logger.info("Trace disabled.") # Debug def before_enable_debug(self): - with self._lock: - self._logger.info("Enabling debug.") - self._stream_formatter.set_trace(True) - for logger in all_loggers(): - logger.setLevel(stdlogging.DEBUG) + # with self._lock: + self._logger.info("Enabling debug.") + self._stream_formatter.set_trace(True) + for logger in all_loggers(): + logger.setLevel(stdlogging.DEBUG) def after_enable_debug(self): self._logger.info("Debug enabled.") def before_disable_debug(self): - with self._lock: - self._logger.info("Disabling debug.") - self._stream_formatter.set_trace(False) - self.enable_default() - + # with self._lock: + self._logger.info("Disabling debug.") + self._stream_formatter.set_trace(False) + self.enable_default() + def after_disable_debug(self): self._logger.info("Debug disabled.") # Disable Logging def before_disable_logging(self): - with self._lock: - self._logger.info("Disabling logging.") - self._stream_formatter.set_trace(False) - for logger in all_loggers(): - logger.setLevel(stdlogging.CRITICAL) + # with self._lock: + self._logger.info("Disabling logging.") + self._stream_formatter.set_trace(False) + for logger in all_loggers(): + logger.setLevel(stdlogging.CRITICAL) # Required API # support log commands for API backwards compatibility From 114671c0b1c80be4edc6a41976867ce664882c9c Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Wed, 20 Mar 2024 10:38:36 -0400 Subject: [PATCH 16/33] Use concurrency primitives to synchronize logging and state change. Since underlying calls to the logger for the various log functions are also concurrent, and the QueueListener is running on a separate thread, these actions must be synchronized so that the order of operations for state setting and logging on either side are respected. --- bittensor/btlogging/format.py | 19 ++++++------- bittensor/btlogging/loggingmachine.py | 41 +++++++++++++++++++++------ 2 files changed, 41 insertions(+), 19 deletions(-) diff --git a/bittensor/btlogging/format.py b/bittensor/btlogging/format.py index 801db421a8..654d042ac6 100644 --- a/bittensor/btlogging/format.py +++ b/bittensor/btlogging/format.py @@ -84,11 +84,11 @@ def format(self, record): # when the logger formatter was instantiated format_orig = self._style._fmt record.levelname = f"{record.levelname:^16}" - with self.lock: - if self.trace is True: - self._style._fmt = LOG_TRACE_FORMATS[record.levelno] - else: - self._style._fmt = LOG_FORMATS[record.levelno] + # with self.lock: + if self.trace is True: + self._style._fmt = LOG_TRACE_FORMATS[record.levelno] + else: + self._style._fmt = LOG_FORMATS[record.levelno] result = super().format(record) self._style._fmt = format_orig @@ -96,11 +96,10 @@ def format(self, record): return result def set_trace(self, state: bool = True): - print(f"setting trace: {state}") - with self.lock: - print(f"lock acquired...") - self.trace = state - print(f"trace set to {state}") + print(f"Setting trace value: {state}") + self.trace = state + print(f"State value set.") + class BtFileFormatter(logging.Formatter): def formatTime(self, record, datefmt=None): diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index efbc511c69..99568e0902 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -1,6 +1,7 @@ import os import sys import atexit +import inspect import threading import multiprocessing as mp import logging as stdlogging @@ -81,7 +82,9 @@ def __init__(self, config: "bittensor.config", name: str=BITTENSOR_LOGGER_NAME): # basics self._queue = mp.Queue(-1) # all self._name = name - self._lock = threading.Lock() + # self._lock = threading.Lock() + self._state_change_event = threading.Event() + self._state_change_event.set() # handlers # TODO: change this to a list of handlers, so that self.listener.handlers @@ -104,7 +107,7 @@ def set_config(self, config): self._config = config if config.logging_dir and config.record_log: logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) - self.info(f"Enabling file logging to: {logfile}") + # self.info(f"Enabling file logging to: {logfile}") self._enable_file_logging(logfile) if config.trace: self.enable_trace() @@ -188,24 +191,25 @@ def _enable_file_logging(self, logfile:str): # if one already exists # if any([isinstance(handler, RotatingFileHandler) for handler in self._handlers]): # return - with self._lock: - file_handler = self._create_file_handler(logfile) - self._handlers.append(file_handler) - self._listener.stop() - self._listener.handlers = tuple(self._handlers) - self._listener.start() + file_handler = self._create_file_handler(logfile) + self._handlers.append(file_handler) + self._listener.stop() + self._listener.handlers = tuple(self._handlers) + self._listener.start() # state transitions # Default Logging def before_enable_default(self): # with self._lock: self._logger.info(f"Enabling default logging.") + self._state_change_event.clear() self._logger.setLevel(stdlogging.INFO) self._stream_formatter.set_trace(False) for logger in all_loggers(): if logger.name == self._name: continue logger.setLevel(stdlogging.CRITICAL) + self._state_change_event.set() def after_enable_default(self): pass @@ -214,9 +218,11 @@ def after_enable_default(self): def before_enable_trace(self): # with self._lock: self._logger.info("Enabling trace.") + self._state_change_event.clear() self._stream_formatter.set_trace(True) for logger in all_loggers(): logger.setLevel(stdlogging.TRACE) + self._state_change_event.set() def after_enable_trace(self): self._logger.info("Trace enabled.") @@ -224,8 +230,10 @@ def after_enable_trace(self): def before_disable_trace(self): # with self._lock: self._logger.info(f"Disabling trace.") + self._state_change_event.clear() self._stream_formatter.set_trace(False) self.enable_default() + self._state_change_event.set() def after_disable_trace(self): self._logger.info("Trace disabled.") @@ -234,7 +242,9 @@ def after_disable_trace(self): def before_enable_debug(self): # with self._lock: self._logger.info("Enabling debug.") + self._state_change_event.clear() self._stream_formatter.set_trace(True) + self._state_change_event.set() for logger in all_loggers(): logger.setLevel(stdlogging.DEBUG) @@ -244,8 +254,10 @@ def after_enable_debug(self): def before_disable_debug(self): # with self._lock: self._logger.info("Disabling debug.") + self._state_change_event.clear() self._stream_formatter.set_trace(False) self.enable_default() + self._state_change_event.set() def after_disable_debug(self): self._logger.info("Debug disabled.") @@ -253,35 +265,46 @@ def after_disable_debug(self): # Disable Logging def before_disable_logging(self): # with self._lock: - self._logger.info("Disabling logging.") + self._logger.info("Disabling logging.") + self._state_change_event.set() self._stream_formatter.set_trace(False) + self._state_change_event.clear() + for logger in all_loggers(): logger.setLevel(stdlogging.CRITICAL) # Required API # support log commands for API backwards compatibility def trace(self, msg, *args, **kwargs): + self._state_change_event.wait() self._logger.trace(msg, *args, **kwargs) def debug(self, msg, *args, **kwargs): + self._state_change_event.wait() self._logger.debug(msg, *args, **kwargs) def info(self, msg, *args, **kwargs): + self._state_change_event.wait() self._logger.info(msg, *args, **kwargs) def success(self, msg, *args, **kwargs): + self._state_change_event.wait() self._logger.success(msg, *args, **kwargs) def warning(self, msg, *args, **kwargs): + self._state_change_event.wait() self._logger.warning(msg, *args, **kwargs) def error(self, msg, *args, **kwargs): + self._state_change_event.wait() self._logger.error(msg, *args, **kwargs) def critical(self, msg, *args, **kwargs): + self._state_change_event.wait() self._logger.critical(msg, *args, **kwargs) def exception(self, msg, *args, **kwargs): + self._state_change_event.wait() self._logger.exception(msg, *args, **kwargs) def on(self): From 3169cf229cd6a46c6cb3e9203ff120063c0159b0 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Wed, 20 Mar 2024 10:49:12 -0400 Subject: [PATCH 17/33] Remove commented locks and return idempotency to file logging enablement. --- bittensor/btlogging/loggingmachine.py | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 99568e0902..2d2ab73c2d 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -189,8 +189,8 @@ def _initialize_external_loggers(self, config): def _enable_file_logging(self, logfile:str): # preserve idempotency; do not create extra filehandlers # if one already exists - # if any([isinstance(handler, RotatingFileHandler) for handler in self._handlers]): - # return + if any([isinstance(handler, RotatingFileHandler) for handler in self._handlers]): + return file_handler = self._create_file_handler(logfile) self._handlers.append(file_handler) self._listener.stop() @@ -200,7 +200,6 @@ def _enable_file_logging(self, logfile:str): # state transitions # Default Logging def before_enable_default(self): - # with self._lock: self._logger.info(f"Enabling default logging.") self._state_change_event.clear() self._logger.setLevel(stdlogging.INFO) @@ -216,7 +215,6 @@ def after_enable_default(self): # Trace def before_enable_trace(self): - # with self._lock: self._logger.info("Enabling trace.") self._state_change_event.clear() self._stream_formatter.set_trace(True) @@ -240,7 +238,6 @@ def after_disable_trace(self): # Debug def before_enable_debug(self): - # with self._lock: self._logger.info("Enabling debug.") self._state_change_event.clear() self._stream_formatter.set_trace(True) @@ -252,7 +249,6 @@ def after_enable_debug(self): self._logger.info("Debug enabled.") def before_disable_debug(self): - # with self._lock: self._logger.info("Disabling debug.") self._state_change_event.clear() self._stream_formatter.set_trace(False) @@ -264,7 +260,6 @@ def after_disable_debug(self): # Disable Logging def before_disable_logging(self): - # with self._lock: self._logger.info("Disabling logging.") self._state_change_event.set() self._stream_formatter.set_trace(False) From f16bb1e67c519e1e59fa43e7ec87e783693842eb Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Wed, 20 Mar 2024 16:19:07 -0400 Subject: [PATCH 18/33] Remove concurrency primities, pause QueueListener during state transitions. Turns out, the only threaded component was the QueueListener, and instead of synchronizing the logger calls, the listener can simply be stopped during a state transition. Thankfully, the StateMachine API makes this change trivial. --- bittensor/btlogging/format.py | 5 +- bittensor/btlogging/helpers.py | 1 + bittensor/btlogging/loggingmachine.py | 92 ++++++++++----------------- 3 files changed, 36 insertions(+), 62 deletions(-) diff --git a/bittensor/btlogging/format.py b/bittensor/btlogging/format.py index 654d042ac6..748f529bb1 100644 --- a/bittensor/btlogging/format.py +++ b/bittensor/btlogging/format.py @@ -65,7 +65,6 @@ class BtStreamFormatter(logging.Formatter): def __init__(self, *args, **kwargs): super().__init__(*args, **kwargs) self.trace = False - self.lock = threading.Lock() def formatTime(self, record, datefmt=None): """ @@ -84,7 +83,7 @@ def format(self, record): # when the logger formatter was instantiated format_orig = self._style._fmt record.levelname = f"{record.levelname:^16}" - # with self.lock: + if self.trace is True: self._style._fmt = LOG_TRACE_FORMATS[record.levelno] else: @@ -96,9 +95,7 @@ def format(self, record): return result def set_trace(self, state: bool = True): - print(f"Setting trace value: {state}") self.trace = state - print(f"State value set.") class BtFileFormatter(logging.Formatter): diff --git a/bittensor/btlogging/helpers.py b/bittensor/btlogging/helpers.py index e81ca36375..35c67ff231 100644 --- a/bittensor/btlogging/helpers.py +++ b/bittensor/btlogging/helpers.py @@ -1,5 +1,6 @@ import logging + def all_loggers(): """ Generator that yields all logger instances in the application. diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 2d2ab73c2d..2844a9c007 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -1,7 +1,6 @@ import os import sys import atexit -import inspect import threading import multiprocessing as mp import logging as stdlogging @@ -18,7 +17,7 @@ BITTENSOR_LOGGER_NAME, DEFAULT_LOG_FILE_NAME, DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, - DEFAULT_LOG_BACKUP_COUNT + DEFAULT_LOG_BACKUP_COUNT, ) @@ -80,46 +79,56 @@ def __init__(self, config: "bittensor.config", name: str=BITTENSOR_LOGGER_NAME): super(LoggingMachine, self).__init__() # basics - self._queue = mp.Queue(-1) # all + self._queue = mp.Queue(-1) self._name = name - # self._lock = threading.Lock() - self._state_change_event = threading.Event() - self._state_change_event.set() - - # handlers - # TODO: change this to a list of handlers, so that self.listener.handlers - # can be updated to modify sinks - # self._handlers = list() - + self._config = config + self._stream_formatter = BtStreamFormatter() self._file_formatter = BtFileFormatter(TRACE_LOG_FORMAT, DATE_FORMAT) - self.set_config(config) + # start with handlers + # In the future, we may want to add options to introduce other handlers + # for things like log aggregation by external services. + self._handlers = list() + + # stream handler, a given + stream_handler = stdlogging.StreamHandler(sys.stdout) + stream_handler.setFormatter(self._stream_formatter) + self._handlers.append(stream_handler) + + # file handler, maybe + if config.record_log and config.logging_dir: + logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) + file_handler = self._create_file_handler(logfile) + self._handlers.append(file_handler) + # configure and start the queue listener + self._listener = self._create_and_start_listener(self._handlers) self._logger = self._initialize_bt_logger(name, config) self._initialize_external_loggers(config) - def get_config(self): return self._config def set_config(self, config): + """ + Set config after initialization, if desired. + """ self._config = config if config.logging_dir and config.record_log: logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) - # self.info(f"Enabling file logging to: {logfile}") self._enable_file_logging(logfile) if config.trace: self.enable_trace() elif config.debug: self.enable_debug() - def _create_listener(self, handlers): + def _create_and_start_listener(self, handlers): """ A listener to receive and publish log records. This listener receives records from a queue populated by the main bittensor - logger, as well as 3rd party loggers. The output sinks + logger, as well as 3rd party loggers. """ listener = QueueListener( @@ -127,6 +136,8 @@ def _create_listener(self, handlers): *handlers, respect_handler_level=True ) + listener.start() + atexit.register(listener.stop) return listener def get_queue(self): @@ -146,23 +157,6 @@ def _initialize_bt_logger(self, name, config): logger = stdlogging.getLogger(name) queue_handler = QueueHandler(self._queue) logger.addHandler(queue_handler) - handlers = list() - - # main handler - stream_handler = stdlogging.StreamHandler(sys.stdout) - stream_handler.setFormatter(self._stream_formatter) - handlers.append(stream_handler) - - if config.record_log and config.logging_dir: - # logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) - # handlers.append(self._create_file_handler(logfile)) - pass - - self._handlers = handlers - self._listener = self._create_listener(handlers) - self._listener.start() - atexit.register(self._listener.stop) - return logger def _create_file_handler(self, logfile: str): @@ -193,22 +187,23 @@ def _enable_file_logging(self, logfile:str): return file_handler = self._create_file_handler(logfile) self._handlers.append(file_handler) - self._listener.stop() self._listener.handlers = tuple(self._handlers) - self._listener.start() # state transitions + def before_transition(self, event, state): + self._listener.stop() + + def after_transition(self, event, state): + self._listener.start() + # Default Logging def before_enable_default(self): self._logger.info(f"Enabling default logging.") - self._state_change_event.clear() self._logger.setLevel(stdlogging.INFO) - self._stream_formatter.set_trace(False) for logger in all_loggers(): if logger.name == self._name: continue logger.setLevel(stdlogging.CRITICAL) - self._state_change_event.set() def after_enable_default(self): pass @@ -216,22 +211,17 @@ def after_enable_default(self): # Trace def before_enable_trace(self): self._logger.info("Enabling trace.") - self._state_change_event.clear() self._stream_formatter.set_trace(True) for logger in all_loggers(): logger.setLevel(stdlogging.TRACE) - self._state_change_event.set() def after_enable_trace(self): self._logger.info("Trace enabled.") def before_disable_trace(self): - # with self._lock: self._logger.info(f"Disabling trace.") - self._state_change_event.clear() self._stream_formatter.set_trace(False) self.enable_default() - self._state_change_event.set() def after_disable_trace(self): self._logger.info("Trace disabled.") @@ -239,9 +229,7 @@ def after_disable_trace(self): # Debug def before_enable_debug(self): self._logger.info("Enabling debug.") - self._state_change_event.clear() self._stream_formatter.set_trace(True) - self._state_change_event.set() for logger in all_loggers(): logger.setLevel(stdlogging.DEBUG) @@ -250,10 +238,8 @@ def after_enable_debug(self): def before_disable_debug(self): self._logger.info("Disabling debug.") - self._state_change_event.clear() self._stream_formatter.set_trace(False) self.enable_default() - self._state_change_event.set() def after_disable_debug(self): self._logger.info("Debug disabled.") @@ -261,9 +247,7 @@ def after_disable_debug(self): # Disable Logging def before_disable_logging(self): self._logger.info("Disabling logging.") - self._state_change_event.set() self._stream_formatter.set_trace(False) - self._state_change_event.clear() for logger in all_loggers(): logger.setLevel(stdlogging.CRITICAL) @@ -271,35 +255,27 @@ def before_disable_logging(self): # Required API # support log commands for API backwards compatibility def trace(self, msg, *args, **kwargs): - self._state_change_event.wait() self._logger.trace(msg, *args, **kwargs) def debug(self, msg, *args, **kwargs): - self._state_change_event.wait() self._logger.debug(msg, *args, **kwargs) def info(self, msg, *args, **kwargs): - self._state_change_event.wait() self._logger.info(msg, *args, **kwargs) def success(self, msg, *args, **kwargs): - self._state_change_event.wait() self._logger.success(msg, *args, **kwargs) def warning(self, msg, *args, **kwargs): - self._state_change_event.wait() self._logger.warning(msg, *args, **kwargs) def error(self, msg, *args, **kwargs): - self._state_change_event.wait() self._logger.error(msg, *args, **kwargs) def critical(self, msg, *args, **kwargs): - self._state_change_event.wait() self._logger.critical(msg, *args, **kwargs) def exception(self, msg, *args, **kwargs): - self._state_change_event.wait() self._logger.exception(msg, *args, **kwargs) def on(self): From bcf5bc62752c72f258a1563131f002b665240479 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 21 Mar 2024 18:37:36 -0400 Subject: [PATCH 19/33] Add unit tests. Some house keeping to the LoggingMachine initialization, and added unit tests to ensure state transitions work as expected. --- bittensor/btlogging/loggingmachine.py | 34 ++-- tests/unit_tests/test_logging.py | 221 +++++++++++++++++++------- 2 files changed, 184 insertions(+), 71 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 2844a9c007..9d3124fc97 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -75,38 +75,48 @@ class LoggingMachine(StateMachine): ) def __init__(self, config: "bittensor.config", name: str=BITTENSOR_LOGGER_NAME): - # set initial state based on config - super(LoggingMachine, self).__init__() # basics + super(LoggingMachine, self).__init__() self._queue = mp.Queue(-1) self._name = name self._config = config + # Formatters + # + # In the future, this may be expanded to a dictionary mapping handler + # types to their respective formatters. self._stream_formatter = BtStreamFormatter() self._file_formatter = BtFileFormatter(TRACE_LOG_FORMAT, DATE_FORMAT) - # start with handlers + # start with handlers for the QueueListener. + # # In the future, we may want to add options to introduce other handlers # for things like log aggregation by external services. - self._handlers = list() + self._handlers = self._configure_handlers(config) + + # configure and start the queue listener + self._listener = self._create_and_start_listener(self._handlers) + + # set up all the loggers + self._logger = self._initialize_bt_logger(name, config) + self._initialize_external_loggers(config) + + def _configure_handlers(self, config) -> list[stdlogging.Handler]: + handlers = list() # stream handler, a given stream_handler = stdlogging.StreamHandler(sys.stdout) stream_handler.setFormatter(self._stream_formatter) - self._handlers.append(stream_handler) - + handlers.append(stream_handler) + # file handler, maybe if config.record_log and config.logging_dir: logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) file_handler = self._create_file_handler(logfile) - self._handlers.append(file_handler) + handlers.append(file_handler) + return handlers - # configure and start the queue listener - self._listener = self._create_and_start_listener(self._handlers) - self._logger = self._initialize_bt_logger(name, config) - self._initialize_external_loggers(config) - def get_config(self): return self._config diff --git a/tests/unit_tests/test_logging.py b/tests/unit_tests/test_logging.py index 696684a267..990d70d767 100644 --- a/tests/unit_tests/test_logging.py +++ b/tests/unit_tests/test_logging.py @@ -1,66 +1,169 @@ -import logging import pytest +import multiprocessing +import logging as stdlogging +from unittest.mock import MagicMock, patch +from bittensor.btlogging import LoggingMachine +from bittensor.btlogging.defines import DEFAULT_LOG_FILE_NAME, BITTENSOR_LOGGER_NAME +from bittensor.btlogging.loggingmachine import LoggingConfig + + +@pytest.fixture(autouse=True, scope="session") +def disable_stdout_streaming(): + # Backup original handlers + original_handlers = stdlogging.root.handlers[:] + + # Remove all handlers that stream to stdout + stdlogging.root.handlers = [h for h in stdlogging.root.handlers if not isinstance(h, stdlogging.StreamHandler)] + + yield # Yield control to the test or fixture setup + + # Restore original handlers after the test + stdlogging.root.handlers = original_handlers + -from bittensor.btlogging import ( - getLogger, - trace, - __enable_non_bt_loggers, - __disable_non_bt_loggers, - __enable_trace, - __disable_logger, - __set_default_logging, - __set_bt_format_logger, - BITTENSOR_LOGGER_NAME -) -from bittensor.btlogging.format import BtStreamFormatter - - -# Mock for all_loggers function @pytest.fixture -def all_loggers_mock(mocker): - mock = mocker.patch('your_module.all_loggers') - mock.return_value = [logging.getLogger(name) for name in ['test_logger1', 'test_logger2']] - return mock +def mock_config(tmp_path): + # Using pytest's tmp_path fixture to generate a temporary directory + log_dir = tmp_path / "logs" + log_dir.mkdir() # Create the temporary directory + log_file_path = log_dir / DEFAULT_LOG_FILE_NAME + + mock_config = LoggingConfig( + debug=False, + trace=False, + record_log=True, + logging_dir=str(log_dir) + ) + + yield mock_config, log_file_path + # Cleanup: No need to explicitly delete the log file or directory, tmp_path does it automatically + + +@pytest.fixture +def logging_machine(mock_config): + config, _ = mock_config + logging_machine = LoggingMachine(config=config) + yield logging_machine + + +def test_initialization(logging_machine, mock_config): + """ + Test initialization of LoggingMachine. + """ + config, log_file_path = mock_config # Unpack to get the log_file_path -def test_getLogger(mock_stdout): - logger = getLogger('testLogger') + assert logging_machine.get_queue() is not None + assert isinstance(logging_machine.get_queue(), multiprocessing.queues.Queue) + assert logging_machine.get_config() == config + # Ensure that handlers are set up correctly + assert any(isinstance(handler, stdlogging.StreamHandler) for handler in logging_machine._handlers) + if config.record_log and config.logging_dir: + assert any(isinstance(handler, stdlogging.FileHandler) for handler in logging_machine._handlers) + assert log_file_path.exists() # Check if log file is created + + +def test_state_transitions(logging_machine, mock_config): + """ + Test state transitions and the associated logging level changes. + """ + config, log_file_path = mock_config + with patch('bittensor.btlogging.loggingmachine.all_loggers') as mocked_all_loggers: + # mock the main bittensor logger, identified by its `name` field + mocked_bt_logger = MagicMock() + mocked_bt_logger.name = BITTENSOR_LOGGER_NAME + # third party loggers are treated differently and silenced under default + # logging settings + mocked_third_party_logger = MagicMock() + logging_machine._logger = mocked_bt_logger + mocked_all_loggers.return_value = [mocked_third_party_logger, mocked_bt_logger] + + # Enable/Disable Debug + # from default + assert logging_machine.current_state_value == "Default" + logging_machine.enable_debug() + assert logging_machine.current_state_value == "Debug" + # check log levels + mocked_bt_logger.setLevel.assert_called_with(stdlogging.DEBUG) + mocked_third_party_logger.setLevel.assert_called_with(stdlogging.DEBUG) + + logging_machine.disable_debug() + + # Enable/Disable Trace + assert logging_machine.current_state_value == "Default" + logging_machine.enable_trace() + assert logging_machine.current_state_value == "Trace" + # check log levels + mocked_bt_logger.setLevel.assert_called_with(stdlogging.TRACE) + mocked_third_party_logger.setLevel.assert_called_with(stdlogging.TRACE) + logging_machine.disable_trace() + assert logging_machine.current_state_value == "Default" + + # Enable Default + logging_machine.enable_debug() + assert logging_machine.current_state_value == "Debug" + logging_machine.enable_default() + assert logging_machine.current_state_value == "Default" + # main logger set to INFO + mocked_bt_logger.setLevel.assert_called_with(stdlogging.INFO) + # 3rd party loggers should be disabled by setting to CRITICAL + mocked_third_party_logger.setLevel.assert_called_with(stdlogging.CRITICAL) + + # Disable Logging + # from default + logging_machine.disable_logging() + assert logging_machine.current_state_value == "Disabled" + mocked_bt_logger.setLevel.assert_called_with(stdlogging.CRITICAL) + mocked_third_party_logger.setLevel.assert_called_with(stdlogging.CRITICAL) + + +def test_enable_file_logging_with_new_config(tmp_path): + """ + Test enabling file logging by setting a new config. + """ + log_dir = tmp_path / "logs" + log_dir.mkdir() # Create the temporary directory + log_file_path = log_dir / DEFAULT_LOG_FILE_NAME + + # check no file handler is created + config = LoggingConfig( + debug=False, + trace=False, + record_log=True, + logging_dir=None + ) + lm = LoggingMachine(config) + assert not any(isinstance(handler, stdlogging.FileHandler) for handler in lm._handlers) + + # check file handler now exists + new_config = LoggingConfig( + debug=False, + trace=False, + record_log=True, + logging_dir=str(log_dir) + ) + lm.set_config(new_config) + assert any(isinstance(handler, stdlogging.FileHandler) for handler in lm._handlers) + + +def test_all_log_levels_output(logging_machine, caplog): + """ + Test that all log levels are captured. + """ + logging_machine.set_trace() -def test_trace_enable(mocker, mock_stdout): - bt_logger = logging.getLogger(BITTENSOR_LOGGER_NAME) - trace() - # This assumes TRACE is a custom level you've set somewhere as logging.TRACE might not be a default level - assert bt_logger.level == logging.TRACE # Use DEBUG for illustration - -def test_enable_non_bt_loggers(all_loggers_mock, mock_stdout): - __enable_non_bt_loggers() - for logger in all_loggers(): - if logger.name != BITTENSOR_LOGGER_NAME: - assert logger.level == logging.INFO # Assuming INFO is the default - assert any([handler.formatter is BtStreamFormatter for handler in logger.handlers]) - -def test_disable_non_bt_loggers(all_loggers_mock, mock_stdout): - __disable_non_bt_loggers() - for logger in all_loggers_mock.return_value: - if logger.name != BITTENSOR_LOGGER_NAME: - assert logger.level == logging.CRITICAL - -def test_enable_trace(mock_stdout): - logger = logging.getLogger('test_trace') - __enable_trace(logger) - # Assuming TRACE level and checking if formatter's trace is enabled - for handler in logger.handlers: - assert isinstance(handler.formatter, BtStreamFormatter) - assert handler.formatter.trace_enabled == True - -def test_disable_logger(mock_stdout): - logger = logging.getLogger('test_disable') - __disable_logger(logger) - # Assuming disabling sets level to CRITICAL and trace to False - assert logger.level == logging.CRITICAL - for handler in logger.handlers: - assert isinstance(handler.formatter, BtStreamFormatter) - assert handler.formatter.trace_enabled == False - -# Further tests would continue in this manner, focusing on the behavior expected from each function. + logging_machine.trace("Test trace") + logging_machine.debug("Test debug") + logging_machine.info("Test info") + logging_machine.success("Test success") + logging_machine.warning("Test warning") + logging_machine.error("Test error") + logging_machine.critical("Test critical") + assert "Test trace" in caplog.text + assert "Test debug" in caplog.text + assert "Test info" in caplog.text + assert "Test success" in caplog.text + assert "Test warning" in caplog.text + assert "Test error" in caplog.text + assert "Test critical" in caplog.text \ No newline at end of file From ef7443d2dfc8f6745e202427b82d5b1467c7beee Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 21 Mar 2024 18:53:13 -0400 Subject: [PATCH 20/33] Update unit test, add function to LoggingMachine for backward compatibility. --- bittensor/btlogging/loggingmachine.py | 4 ++++ tests/unit_tests/test_metagraph.py | 10 +++------- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 9d3124fc97..34a26597ca 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -264,6 +264,10 @@ def before_disable_logging(self): # Required API # support log commands for API backwards compatibility + def __trace_on__(self): + if not self.current_state_value == "Trace": + self.enable_trace() + def trace(self, msg, *args, **kwargs): self._logger.trace(msg, *args, **kwargs) diff --git a/tests/unit_tests/test_metagraph.py b/tests/unit_tests/test_metagraph.py index 3cd9d1896a..b5264b2a03 100644 --- a/tests/unit_tests/test_metagraph.py +++ b/tests/unit_tests/test_metagraph.py @@ -168,15 +168,11 @@ def __contains__(self, item): ], ) def test_sync_warning_cases( - block, test_id, metagraph_instance, mock_subtensor, loguru_sink + block, test_id, metagraph_instance, mock_subtensor, caplog ): - handler_id = logger.add(loguru_sink.write, level="WARNING") - metagraph_instance.sync(block=block, lite=True, subtensor=mock_subtensor) expected_message = "Attempting to sync longer than 300 blocks ago on a non-archive node. Please use the 'archive' network for subtensor and retry." assert ( - expected_message in loguru_sink - ), f"Test ID: {test_id} - Expected warning message not found in Loguru sink." - - logger.remove(handler_id) + expected_message in caplog.text + ), f"Test ID: {test_id} - Expected warning message not found in Loguru sink." \ No newline at end of file From ab9ad3db8cedbc24ff622e6e082640ab4afde1b7 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 21 Mar 2024 18:58:44 -0400 Subject: [PATCH 21/33] Black fixes. --- bittensor/btlogging/__init__.py | 3 +- bittensor/btlogging/defines.py | 6 +- bittensor/btlogging/format.py | 32 +++++----- bittensor/btlogging/helpers.py | 2 +- bittensor/btlogging/loggingmachine.py | 88 ++++++++++++--------------- tests/unit_tests/test_logging.py | 51 ++++++++-------- tests/unit_tests/test_metagraph.py | 6 +- 7 files changed, 88 insertions(+), 100 deletions(-) diff --git a/bittensor/btlogging/__init__.py b/bittensor/btlogging/__init__.py index 670088f2c2..5abc731ab5 100644 --- a/bittensor/btlogging/__init__.py +++ b/bittensor/btlogging/__init__.py @@ -64,6 +64,7 @@ def add_args(parser: argparse.ArgumentParser, prefix: str = None): # re-parsing arguments. pass + def config(): """Get config from the argument parser. @@ -75,4 +76,4 @@ def config(): return bittensor.config(parser, args=[]) -logging = LoggingMachine(config()) \ No newline at end of file +logging = LoggingMachine(config()) diff --git a/bittensor/btlogging/defines.py b/bittensor/btlogging/defines.py index a51a4c5d25..605ff94df4 100644 --- a/bittensor/btlogging/defines.py +++ b/bittensor/btlogging/defines.py @@ -1,7 +1,9 @@ BASE_LOG_FORMAT = "%(asctime)s | %(levelname)s | %(message)s" -TRACE_LOG_FORMAT = f"%(asctime)s | %(levelname)s | %(name)s:%(filename)s:%(lineno)s | %(message)s" +TRACE_LOG_FORMAT = ( + f"%(asctime)s | %(levelname)s | %(name)s:%(filename)s:%(lineno)s | %(message)s" +) DATE_FORMAT = "%Y-%m-%d %H:%M:%S" BITTENSOR_LOGGER_NAME = "bittensor" DEFAULT_LOG_FILE_NAME = "bittensor.log" DEFAULT_MAX_ROTATING_LOG_FILE_SIZE = 25 * 1024 * 1024 -DEFAULT_LOG_BACKUP_COUNT = 10 \ No newline at end of file +DEFAULT_LOG_BACKUP_COUNT = 10 diff --git a/bittensor/btlogging/format.py b/bittensor/btlogging/format.py index 748f529bb1..ea55c0a68b 100644 --- a/bittensor/btlogging/format.py +++ b/bittensor/btlogging/format.py @@ -2,12 +2,7 @@ import time import logging import threading -from colorama import ( - init, - Fore, - Back, - Style -) +from colorama import init, Fore, Back, Style from bittensor.btlogging.helpers import get_max_logger_name_length @@ -16,13 +11,15 @@ TRACE_LEVELV_NUM = 5 SUCCESS_LEVELV_NUM = 21 + def trace(self, message, *args, **kws): if self.isEnabledFor(TRACE_LEVELV_NUM): - self._log(TRACE_LEVELV_NUM, message, args, **kws) + self._log(TRACE_LEVELV_NUM, message, args, **kws) + def success(self, message, *args, **kws): if self.isEnabledFor(SUCCESS_LEVELV_NUM): - self._log(SUCCESS_LEVELV_NUM, message, args, **kws) + self._log(SUCCESS_LEVELV_NUM, message, args, **kws) logging.SUCCESS = SUCCESS_LEVELV_NUM @@ -47,21 +44,20 @@ def success(self, message, *args, **kws): LOG_FORMATS = { - level: f"{Fore.BLUE}%(asctime)s{Fore.RESET} | {Style.BRIGHT}{color}%(levelname)s\033[0m | %(message)s" + level: f"{Fore.BLUE}%(asctime)s{Fore.RESET} | {Style.BRIGHT}{color}%(levelname)s\033[0m | %(message)s" for level, color in log_level_color_prefix.items() } LOG_TRACE_FORMATS = { - level: f"{Fore.BLUE}%(asctime)s{Fore.RESET}"\ - f" | {Style.BRIGHT}{color}%(levelname)s{Fore.RESET}{Back.RESET}{Style.RESET_ALL}"\ - f" | %(name)s:%(filename)s:%(lineno)s"\ - f" | %(message)s" + level: f"{Fore.BLUE}%(asctime)s{Fore.RESET}" + f" | {Style.BRIGHT}{color}%(levelname)s{Fore.RESET}{Back.RESET}{Style.RESET_ALL}" + f" | %(name)s:%(filename)s:%(lineno)s" + f" | %(message)s" for level, color in log_level_color_prefix.items() } class BtStreamFormatter(logging.Formatter): - def __init__(self, *args, **kwargs): super().__init__(*args, **kwargs) self.trace = False @@ -77,7 +73,7 @@ def formatTime(self, record, datefmt=None): s = time.strftime("%Y-%m-%d %H:%M:%S", created) s += ".{:03d}".format(int(record.msecs)) return s - + def format(self, record): # Save the original format configured by the user # when the logger formatter was instantiated @@ -93,7 +89,7 @@ def format(self, record): self._style._fmt = format_orig return result - + def set_trace(self, state: bool = True): self.trace = state @@ -110,7 +106,7 @@ def formatTime(self, record, datefmt=None): s = time.strftime("%Y-%m-%d %H:%M:%S", created) s += ".{:03d}".format(int(record.msecs)) return s - + def format(self, record): record.levelname = f"{record.levelname:^16}" - return super().format(record) \ No newline at end of file + return super().format(record) diff --git a/bittensor/btlogging/helpers.py b/bittensor/btlogging/helpers.py index 35c67ff231..e4d5b0492c 100644 --- a/bittensor/btlogging/helpers.py +++ b/bittensor/btlogging/helpers.py @@ -41,4 +41,4 @@ def get_max_logger_name_length(): for name in all_logger_names(): if len(name) > max_length: max_length = len(name) - return max_length \ No newline at end of file + return max_length diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 34a26597ca..3917f960bf 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -46,26 +46,16 @@ class LoggingMachine(StateMachine): ) enable_trace = ( - Default.to(Trace) - | Debug.to(Trace) - | Disabled.to(Trace) - | Trace.to(Trace) + Default.to(Trace) | Debug.to(Trace) | Disabled.to(Trace) | Trace.to(Trace) ) enable_debug = ( - Default.to(Debug) - | Trace.to(Debug) - | Disabled.to(Debug) - | Debug.to(Debug) + Default.to(Debug) | Trace.to(Debug) | Disabled.to(Debug) | Debug.to(Debug) ) - disable_trace = ( - Trace.to(Default) - ) + disable_trace = Trace.to(Default) - disable_debug = ( - Debug.to(Default) - ) + disable_debug = Debug.to(Default) disable_logging = ( Trace.to(Disabled) @@ -74,14 +64,13 @@ class LoggingMachine(StateMachine): | Disabled.to(Disabled) ) - def __init__(self, config: "bittensor.config", name: str=BITTENSOR_LOGGER_NAME): - + def __init__(self, config: "bittensor.config", name: str = BITTENSOR_LOGGER_NAME): # basics super(LoggingMachine, self).__init__() self._queue = mp.Queue(-1) self._name = name self._config = config - + # Formatters # # In the future, this may be expanded to a dictionary mapping handler @@ -101,7 +90,7 @@ def __init__(self, config: "bittensor.config", name: str=BITTENSOR_LOGGER_NAME): # set up all the loggers self._logger = self._initialize_bt_logger(name, config) self._initialize_external_loggers(config) - + def _configure_handlers(self, config) -> list[stdlogging.Handler]: handlers = list() @@ -109,10 +98,12 @@ def _configure_handlers(self, config) -> list[stdlogging.Handler]: stream_handler = stdlogging.StreamHandler(sys.stdout) stream_handler.setFormatter(self._stream_formatter) handlers.append(stream_handler) - + # file handler, maybe if config.record_log and config.logging_dir: - logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) + logfile = os.path.abspath( + os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME) + ) file_handler = self._create_file_handler(logfile) handlers.append(file_handler) return handlers @@ -126,7 +117,9 @@ def set_config(self, config): """ self._config = config if config.logging_dir and config.record_log: - logfile = os.path.abspath(os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME)) + logfile = os.path.abspath( + os.path.join(config.logging_dir, DEFAULT_LOG_FILE_NAME) + ) self._enable_file_logging(logfile) if config.trace: self.enable_trace() @@ -136,16 +129,12 @@ def set_config(self, config): def _create_and_start_listener(self, handlers): """ A listener to receive and publish log records. - + This listener receives records from a queue populated by the main bittensor logger, as well as 3rd party loggers. """ - listener = QueueListener( - self._queue, - *handlers, - respect_handler_level=True - ) + listener = QueueListener(self._queue, *handlers, respect_handler_level=True) listener.start() atexit.register(listener.stop) return listener @@ -160,8 +149,8 @@ def _initialize_bt_logger(self, name, config): """ Initialize logging for bittensor. - Since the initial state is Default, logging level for the module logger - is INFO, and all third-party loggers are silenced. Subsequent state + Since the initial state is Default, logging level for the module logger + is INFO, and all third-party loggers are silenced. Subsequent state transitions will handle all logger outputs. """ logger = stdlogging.getLogger(name) @@ -171,10 +160,10 @@ def _initialize_bt_logger(self, name, config): def _create_file_handler(self, logfile: str): file_handler = RotatingFileHandler( - logfile, - maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, - backupCount=DEFAULT_LOG_BACKUP_COUNT - ) + logfile, + maxBytes=DEFAULT_MAX_ROTATING_LOG_FILE_SIZE, + backupCount=DEFAULT_LOG_BACKUP_COUNT, + ) file_handler.setFormatter(self._file_formatter) file_handler.setLevel(stdlogging.TRACE) return file_handler @@ -188,12 +177,14 @@ def _initialize_external_loggers(self, config): logger.removeHandler(handler) queue_handler = QueueHandler(self._queue) logger.addHandler(queue_handler) - logger.setLevel(stdlogging.CRITICAL) + logger.setLevel(stdlogging.CRITICAL) - def _enable_file_logging(self, logfile:str): + def _enable_file_logging(self, logfile: str): # preserve idempotency; do not create extra filehandlers # if one already exists - if any([isinstance(handler, RotatingFileHandler) for handler in self._handlers]): + if any( + [isinstance(handler, RotatingFileHandler) for handler in self._handlers] + ): return file_handler = self._create_file_handler(logfile) self._handlers.append(file_handler) @@ -202,7 +193,7 @@ def _enable_file_logging(self, logfile:str): # state transitions def before_transition(self, event, state): self._listener.stop() - + def after_transition(self, event, state): self._listener.start() @@ -232,7 +223,7 @@ def before_disable_trace(self): self._logger.info(f"Disabling trace.") self._stream_formatter.set_trace(False) self.enable_default() - + def after_disable_trace(self): self._logger.info("Trace disabled.") @@ -253,17 +244,17 @@ def before_disable_debug(self): def after_disable_debug(self): self._logger.info("Debug disabled.") - + # Disable Logging def before_disable_logging(self): - self._logger.info("Disabling logging.") + self._logger.info("Disabling logging.") self._stream_formatter.set_trace(False) - + for logger in all_loggers(): logger.setLevel(stdlogging.CRITICAL) - + # Required API - # support log commands for API backwards compatibility + # support log commands for API backwards compatibility def __trace_on__(self): if not self.current_state_value == "Trace": self.enable_trace() @@ -288,7 +279,7 @@ def error(self, msg, *args, **kwargs): def critical(self, msg, *args, **kwargs): self._logger.critical(msg, *args, **kwargs) - + def exception(self, msg, *args, **kwargs): self._logger.exception(msg, *args, **kwargs) @@ -299,23 +290,22 @@ def on(self): def off(self): self.disable_logging() - def set_debug(self, on: bool=True): + def set_debug(self, on: bool = True): if on and not self.current_state_value == "Debug": self.enable_debug() elif not on: if self.current_state_value == "Debug": self.disable_debug() - - def set_trace(self, on: bool=True): + def set_trace(self, on: bool = True): if on and not self.current_state_value == "Trace": self.enable_trace() elif not on: if self.current_state_value == "Trace": self.disable_trace() - + def get_level(self): return self._logger.level def help(self): - pass \ No newline at end of file + pass diff --git a/tests/unit_tests/test_logging.py b/tests/unit_tests/test_logging.py index 990d70d767..1822fc86ef 100644 --- a/tests/unit_tests/test_logging.py +++ b/tests/unit_tests/test_logging.py @@ -11,12 +11,16 @@ def disable_stdout_streaming(): # Backup original handlers original_handlers = stdlogging.root.handlers[:] - + # Remove all handlers that stream to stdout - stdlogging.root.handlers = [h for h in stdlogging.root.handlers if not isinstance(h, stdlogging.StreamHandler)] - + stdlogging.root.handlers = [ + h + for h in stdlogging.root.handlers + if not isinstance(h, stdlogging.StreamHandler) + ] + yield # Yield control to the test or fixture setup - + # Restore original handlers after the test stdlogging.root.handlers = original_handlers @@ -29,10 +33,7 @@ def mock_config(tmp_path): log_file_path = log_dir / DEFAULT_LOG_FILE_NAME mock_config = LoggingConfig( - debug=False, - trace=False, - record_log=True, - logging_dir=str(log_dir) + debug=False, trace=False, record_log=True, logging_dir=str(log_dir) ) yield mock_config, log_file_path @@ -55,11 +56,17 @@ def test_initialization(logging_machine, mock_config): assert logging_machine.get_queue() is not None assert isinstance(logging_machine.get_queue(), multiprocessing.queues.Queue) assert logging_machine.get_config() == config - + # Ensure that handlers are set up correctly - assert any(isinstance(handler, stdlogging.StreamHandler) for handler in logging_machine._handlers) + assert any( + isinstance(handler, stdlogging.StreamHandler) + for handler in logging_machine._handlers + ) if config.record_log and config.logging_dir: - assert any(isinstance(handler, stdlogging.FileHandler) for handler in logging_machine._handlers) + assert any( + isinstance(handler, stdlogging.FileHandler) + for handler in logging_machine._handlers + ) assert log_file_path.exists() # Check if log file is created @@ -68,7 +75,7 @@ def test_state_transitions(logging_machine, mock_config): Test state transitions and the associated logging level changes. """ config, log_file_path = mock_config - with patch('bittensor.btlogging.loggingmachine.all_loggers') as mocked_all_loggers: + with patch("bittensor.btlogging.loggingmachine.all_loggers") as mocked_all_loggers: # mock the main bittensor logger, identified by its `name` field mocked_bt_logger = MagicMock() mocked_bt_logger.name = BITTENSOR_LOGGER_NAME @@ -86,7 +93,7 @@ def test_state_transitions(logging_machine, mock_config): # check log levels mocked_bt_logger.setLevel.assert_called_with(stdlogging.DEBUG) mocked_third_party_logger.setLevel.assert_called_with(stdlogging.DEBUG) - + logging_machine.disable_debug() # Enable/Disable Trace @@ -126,21 +133,15 @@ def test_enable_file_logging_with_new_config(tmp_path): log_file_path = log_dir / DEFAULT_LOG_FILE_NAME # check no file handler is created - config = LoggingConfig( - debug=False, - trace=False, - record_log=True, - logging_dir=None - ) + config = LoggingConfig(debug=False, trace=False, record_log=True, logging_dir=None) lm = LoggingMachine(config) - assert not any(isinstance(handler, stdlogging.FileHandler) for handler in lm._handlers) + assert not any( + isinstance(handler, stdlogging.FileHandler) for handler in lm._handlers + ) # check file handler now exists new_config = LoggingConfig( - debug=False, - trace=False, - record_log=True, - logging_dir=str(log_dir) + debug=False, trace=False, record_log=True, logging_dir=str(log_dir) ) lm.set_config(new_config) assert any(isinstance(handler, stdlogging.FileHandler) for handler in lm._handlers) @@ -166,4 +167,4 @@ def test_all_log_levels_output(logging_machine, caplog): assert "Test success" in caplog.text assert "Test warning" in caplog.text assert "Test error" in caplog.text - assert "Test critical" in caplog.text \ No newline at end of file + assert "Test critical" in caplog.text diff --git a/tests/unit_tests/test_metagraph.py b/tests/unit_tests/test_metagraph.py index b5264b2a03..0c1aac2637 100644 --- a/tests/unit_tests/test_metagraph.py +++ b/tests/unit_tests/test_metagraph.py @@ -167,12 +167,10 @@ def __contains__(self, item): (300, "warning_case_block_greater_than_300"), ], ) -def test_sync_warning_cases( - block, test_id, metagraph_instance, mock_subtensor, caplog -): +def test_sync_warning_cases(block, test_id, metagraph_instance, mock_subtensor, caplog): metagraph_instance.sync(block=block, lite=True, subtensor=mock_subtensor) expected_message = "Attempting to sync longer than 300 blocks ago on a non-archive node. Please use the 'archive' network for subtensor and retry." assert ( expected_message in caplog.text - ), f"Test ID: {test_id} - Expected warning message not found in Loguru sink." \ No newline at end of file + ), f"Test ID: {test_id} - Expected warning message not found in Loguru sink." From 913b32407c2f279f050c004d514a2e70e88ad8ed Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 21 Mar 2024 19:47:51 -0400 Subject: [PATCH 22/33] Add support for prefix and sufix args in logging API. Add support for emojis and color setting within messages --- bittensor/btlogging/format.py | 22 +++++++++++++++++ bittensor/btlogging/loggingmachine.py | 35 ++++++++++++++++++--------- 2 files changed, 45 insertions(+), 12 deletions(-) diff --git a/bittensor/btlogging/format.py b/bittensor/btlogging/format.py index ea55c0a68b..0ea77f1527 100644 --- a/bittensor/btlogging/format.py +++ b/bittensor/btlogging/format.py @@ -30,6 +30,22 @@ def success(self, message, *args, **kws): logging.addLevelName(TRACE_LEVELV_NUM, "TRACE") logging.Logger.trace = trace +emoji_map = { + ':white_heavy_check_mark:': '✅', + ':cross_mark:': '❌', + ':satellite:': '🛰️', +} + + +color_map = { + '': Fore.RED, + '': Style.RESET_ALL, + '': Fore.BLUE, + '': Style.RESET_ALL, + '': Fore.GREEN, + '': Style.RESET_ALL, +} + log_level_color_prefix = { logging.NOTSET: Fore.RESET, @@ -85,6 +101,12 @@ def format(self, record): else: self._style._fmt = LOG_FORMATS[record.levelno] + for text, emoji in emoji_map.items(): + record.msg = record.msg.replace(text, emoji) + # Apply color specifiers + for text, color in color_map.items(): + record.msg = record.msg.replace(text, color) + result = super().format(record) self._style._fmt = format_orig diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 3917f960bf..c6c6d536a8 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -140,10 +140,13 @@ def _create_and_start_listener(self, handlers): return listener def get_queue(self): - if hasattr(self, "_queue"): - return self._queue - else: - raise AttributeError("File logging is not enabled, no queue available.") + """ + Get the queue the QueueListener is publishing from. + + To set up logging in a separate process, a QueueHandler must + be added to all the desired loggers. + """ + return self._queue def _initialize_bt_logger(self, name, config): """ @@ -259,28 +262,36 @@ def __trace_on__(self): if not self.current_state_value == "Trace": self.enable_trace() - def trace(self, msg, *args, **kwargs): + def trace(self, msg="", prefix="", sufix="", *args, **kwargs): + msg = f"{prefix} - {msg} - {sufix}" self._logger.trace(msg, *args, **kwargs) - def debug(self, msg, *args, **kwargs): + def debug(self, msg="", prefix="", sufix="", *args, **kwargs): + msg = f"{prefix} - {msg} - {sufix}" self._logger.debug(msg, *args, **kwargs) - def info(self, msg, *args, **kwargs): + def info(self, msg="", prefix="", sufix="", *args, **kwargs): + msg = f"{prefix} - {msg} - {sufix}" self._logger.info(msg, *args, **kwargs) - def success(self, msg, *args, **kwargs): + def success(self, msg="", prefix="", sufix="", *args, **kwargs): + msg = f"{prefix} - {msg} - {sufix}" self._logger.success(msg, *args, **kwargs) - def warning(self, msg, *args, **kwargs): + def warning(self, msg="", prefix="", sufix="", *args, **kwargs): + msg = f"{prefix} - {msg} - {sufix}" self._logger.warning(msg, *args, **kwargs) - def error(self, msg, *args, **kwargs): + def error(self, msg="", prefix="", sufix="", *args, **kwargs): + msg = f"{prefix} - {msg} - {sufix}" self._logger.error(msg, *args, **kwargs) - def critical(self, msg, *args, **kwargs): + def critical(self, msg="", prefix="", sufix="", *args, **kwargs): + msg = f"{prefix} - {msg} - {sufix}" self._logger.critical(msg, *args, **kwargs) - def exception(self, msg, *args, **kwargs): + def exception(self, msg="", prefix="", sufix="", *args, **kwargs): + msg = f"{prefix} - {msg} - {sufix}" self._logger.exception(msg, *args, **kwargs) def on(self): From 37367bcd90926084bced27e705d4c93c24c65ff9 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 21 Mar 2024 22:59:58 -0400 Subject: [PATCH 23/33] Remove unused imports. Black fix. --- bittensor/btlogging/format.py | 41 +++++++++++++-------------- bittensor/btlogging/loggingmachine.py | 5 ++-- 2 files changed, 21 insertions(+), 25 deletions(-) diff --git a/bittensor/btlogging/format.py b/bittensor/btlogging/format.py index 0ea77f1527..64a4ca45b6 100644 --- a/bittensor/btlogging/format.py +++ b/bittensor/btlogging/format.py @@ -1,49 +1,46 @@ -import os import time import logging -import threading from colorama import init, Fore, Back, Style -from bittensor.btlogging.helpers import get_max_logger_name_length init(autoreset=True) -TRACE_LEVELV_NUM = 5 -SUCCESS_LEVELV_NUM = 21 +TRACE_LEVEL_NUM = 5 +SUCCESS_LEVEL_NUM = 21 def trace(self, message, *args, **kws): - if self.isEnabledFor(TRACE_LEVELV_NUM): - self._log(TRACE_LEVELV_NUM, message, args, **kws) + if self.isEnabledFor(TRACE_LEVEL_NUM): + self._log(TRACE_LEVEL_NUM, message, args, **kws) def success(self, message, *args, **kws): - if self.isEnabledFor(SUCCESS_LEVELV_NUM): - self._log(SUCCESS_LEVELV_NUM, message, args, **kws) + if self.isEnabledFor(SUCCESS_LEVEL_NUM): + self._log(SUCCESS_LEVEL_NUM, message, args, **kws) -logging.SUCCESS = SUCCESS_LEVELV_NUM -logging.addLevelName(SUCCESS_LEVELV_NUM, "SUCCESS") +logging.SUCCESS = SUCCESS_LEVEL_NUM +logging.addLevelName(SUCCESS_LEVEL_NUM, "SUCCESS") logging.Logger.success = success -logging.TRACE = TRACE_LEVELV_NUM -logging.addLevelName(TRACE_LEVELV_NUM, "TRACE") +logging.TRACE = TRACE_LEVEL_NUM +logging.addLevelName(TRACE_LEVEL_NUM, "TRACE") logging.Logger.trace = trace emoji_map = { - ':white_heavy_check_mark:': '✅', - ':cross_mark:': '❌', - ':satellite:': '🛰️', + ":white_heavy_check_mark:": "✅", + ":cross_mark:": "❌", + ":satellite:": "🛰️", } color_map = { - '': Fore.RED, - '': Style.RESET_ALL, - '': Fore.BLUE, - '': Style.RESET_ALL, - '': Fore.GREEN, - '': Style.RESET_ALL, + "": Fore.RED, + "": Style.RESET_ALL, + "": Fore.BLUE, + "": Style.RESET_ALL, + "": Fore.GREEN, + "": Style.RESET_ALL, } diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index c6c6d536a8..630ab2e045 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -1,17 +1,16 @@ import os import sys import atexit -import threading import multiprocessing as mp import logging as stdlogging from typing import NamedTuple from statemachine import StateMachine, State from logging.handlers import QueueHandler, QueueListener, RotatingFileHandler +import bittensor.config from bittensor.btlogging.format import BtStreamFormatter, BtFileFormatter from bittensor.btlogging.helpers import all_loggers from bittensor.btlogging.defines import ( - BASE_LOG_FORMAT, TRACE_LOG_FORMAT, DATE_FORMAT, BITTENSOR_LOGGER_NAME, @@ -64,7 +63,7 @@ class LoggingMachine(StateMachine): | Disabled.to(Disabled) ) - def __init__(self, config: "bittensor.config", name: str = BITTENSOR_LOGGER_NAME): + def __init__(self, config: bittensor.config, name: str = BITTENSOR_LOGGER_NAME): # basics super(LoggingMachine, self).__init__() self._queue = mp.Queue(-1) From 02360d91b412f2008f57baa998d88755122a7d33 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Thu, 21 Mar 2024 23:12:48 -0400 Subject: [PATCH 24/33] Fix property check for LoggingMachine --- bittensor/btlogging/loggingmachine.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 630ab2e045..e50168b177 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -257,9 +257,9 @@ def before_disable_logging(self): # Required API # support log commands for API backwards compatibility + @property def __trace_on__(self): - if not self.current_state_value == "Trace": - self.enable_trace() + return self.current_state_value == "Trace" def trace(self, msg="", prefix="", sufix="", *args, **kwargs): msg = f"{prefix} - {msg} - {sufix}" From cf2d0218fa51e57f3420b19c6ae0bd78687dd0db Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Fri, 22 Mar 2024 13:39:54 -0400 Subject: [PATCH 25/33] Return required API for args and config --- bittensor/btlogging/__init__.py | 52 +------------------------- bittensor/btlogging/loggingmachine.py | 54 +++++++++++++++++++++++++++ 2 files changed, 55 insertions(+), 51 deletions(-) diff --git a/bittensor/btlogging/__init__.py b/bittensor/btlogging/__init__.py index 5abc731ab5..16dc150cf0 100644 --- a/bittensor/btlogging/__init__.py +++ b/bittensor/btlogging/__init__.py @@ -26,54 +26,4 @@ from bittensor.btlogging.loggingmachine import LoggingMachine -def add_args(parser: argparse.ArgumentParser, prefix: str = None): - """Accept specific arguments fro parser""" - prefix_str = "" if prefix == None else prefix + "." - try: - default_logging_debug = os.getenv("BT_LOGGING_DEBUG") or False - default_logging_trace = os.getenv("BT_LOGGING_TRACE") or False - default_logging_record_log = os.getenv("BT_LOGGING_RECORD_LOG") or False - default_logging_logging_dir = ( - os.getenv("BT_LOGGING_LOGGING_DIR") or "~/.bittensor/miners" - ) - parser.add_argument( - "--" + prefix_str + "logging.debug", - action="store_true", - help="""Turn on bittensor debugging information""", - default=default_logging_debug, - ) - parser.add_argument( - "--" + prefix_str + "logging.trace", - action="store_true", - help="""Turn on bittensor trace level information""", - default=default_logging_trace, - ) - parser.add_argument( - "--" + prefix_str + "logging.record_log", - action="store_true", - help="""Turns on logging to file.""", - default=default_logging_record_log, - ) - parser.add_argument( - "--" + prefix_str + "logging.logging_dir", - type=str, - help="Logging default root directory.", - default=default_logging_logging_dir, - ) - except argparse.ArgumentError: - # re-parsing arguments. - pass - - -def config(): - """Get config from the argument parser. - - Return: - bittensor.config object - """ - parser = argparse.ArgumentParser() - add_args(parser) - return bittensor.config(parser, args=[]) - - -logging = LoggingMachine(config()) +logging = LoggingMachine(LoggingMachine.config()) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index e50168b177..1b216b6cc3 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -1,6 +1,7 @@ import os import sys import atexit +import argparse import multiprocessing as mp import logging as stdlogging from typing import NamedTuple @@ -316,6 +317,59 @@ def set_trace(self, on: bool = True): def get_level(self): return self._logger.level + + def check_config(self): + assert self._config def help(self): pass + + @classmethod + def add_args(cls, parser: argparse.ArgumentParser, prefix: str = None): + """Accept specific arguments fro parser""" + prefix_str = "" if prefix == None else prefix + "." + try: + default_logging_debug = os.getenv("BT_LOGGING_DEBUG") or False + default_logging_trace = os.getenv("BT_LOGGING_TRACE") or False + default_logging_record_log = os.getenv("BT_LOGGING_RECORD_LOG") or False + default_logging_logging_dir = ( + os.getenv("BT_LOGGING_LOGGING_DIR") or "~/.bittensor/miners" + ) + parser.add_argument( + "--" + prefix_str + "logging.debug", + action="store_true", + help="""Turn on bittensor debugging information""", + default=default_logging_debug, + ) + parser.add_argument( + "--" + prefix_str + "logging.trace", + action="store_true", + help="""Turn on bittensor trace level information""", + default=default_logging_trace, + ) + parser.add_argument( + "--" + prefix_str + "logging.record_log", + action="store_true", + help="""Turns on logging to file.""", + default=default_logging_record_log, + ) + parser.add_argument( + "--" + prefix_str + "logging.logging_dir", + type=str, + help="Logging default root directory.", + default=default_logging_logging_dir, + ) + except argparse.ArgumentError: + # re-parsing arguments. + pass + + @classmethod + def config(cls): + """Get config from the argument parser. + + Return: + bittensor.config object + """ + parser = argparse.ArgumentParser() + cls.add_args(parser) + return bittensor.config(parser, args=[]) From 6ed44f9c29b0278717837a44b3d22da2d3b1e5db Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Fri, 22 Mar 2024 13:46:26 -0400 Subject: [PATCH 26/33] Fix check_config api. --- bittensor/btlogging/loggingmachine.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 1b216b6cc3..a6530fabeb 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -318,8 +318,8 @@ def set_trace(self, on: bool = True): def get_level(self): return self._logger.level - def check_config(self): - assert self._config + def check_config(self, config: bittensor.config): + assert config.logging def help(self): pass From 41f3769033f0e85ddffa11e55977ad19b60a1101 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Fri, 22 Mar 2024 14:00:13 -0400 Subject: [PATCH 27/33] Override __call__ for LoggingMachine object to match previous API --- bittensor/btlogging/loggingmachine.py | 28 +++++++++++++++++++++++++++ 1 file changed, 28 insertions(+) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index a6530fabeb..ebe2161189 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -1,5 +1,6 @@ import os import sys +import copy import atexit import argparse import multiprocessing as mp @@ -373,3 +374,30 @@ def config(cls): parser = argparse.ArgumentParser() cls.add_args(parser) return bittensor.config(parser, args=[]) + + def __call__( + self, + config: bittensor.config = None, + debug: bool = None, + trace: bool = None, + record_log: bool = None, + logging_dir: str = None, + ): + if config is not None: + cfg = copy.deepcopy(config) + if debug is not None: + cfg.debug = debug + elif trace is not None: + cfg.trace = trace + if record_log is not None: + cfg.record_log = record_log + if logging_dir is not None: + cfg.logging_dir = logging_dir + else: + cfg = LoggingConfig( + debug=debug, + trace=trace, + record_log=record_log, + logging_dir=logging_dir + ) + self.set_config(cfg) From 95fd1f38518f3ae1498af00a9d09dce1c0cfdf59 Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Fri, 22 Mar 2024 14:55:38 -0400 Subject: [PATCH 28/33] Disable 3rd party loggers for now, and separate out toggling to a separate function call not bound to LoggingMachine state. --- bittensor/btlogging/loggingmachine.py | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index ebe2161189..644ce9b224 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -90,7 +90,7 @@ def __init__(self, config: bittensor.config, name: str = BITTENSOR_LOGGER_NAME): # set up all the loggers self._logger = self._initialize_bt_logger(name, config) - self._initialize_external_loggers(config) + self.disable_third_party_loggers() def _configure_handlers(self, config) -> list[stdlogging.Handler]: handlers = list() @@ -171,17 +171,22 @@ def _create_file_handler(self, logfile: str): file_handler.setFormatter(self._file_formatter) file_handler.setLevel(stdlogging.TRACE) return file_handler - - def _initialize_external_loggers(self, config): + + def enable_third_party_loggers(self): + for logger in all_loggers(): + if logger.name == self._name: + continue + queue_handler = QueueHandler(self._queue) + logger.addHandler(queue_handler) + logger.setLevel(self._logger.level) + + def disable_third_party_loggers(self): # remove all handlers for logger in all_loggers(): if logger.name == self._name: continue for handler in logger.handlers: logger.removeHandler(handler) - queue_handler = QueueHandler(self._queue) - logger.addHandler(queue_handler) - logger.setLevel(stdlogging.CRITICAL) def _enable_file_logging(self, logfile: str): # preserve idempotency; do not create extra filehandlers From 99547f0bb522b94e2279ff7385f31856a9e5b2cb Mon Sep 17 00:00:00 2001 From: Sepehr Ghavam Date: Fri, 22 Mar 2024 16:58:30 -0400 Subject: [PATCH 29/33] Black fix. --- bittensor/btlogging/loggingmachine.py | 19 ++++++++----------- 1 file changed, 8 insertions(+), 11 deletions(-) diff --git a/bittensor/btlogging/loggingmachine.py b/bittensor/btlogging/loggingmachine.py index 644ce9b224..69fdc9e69d 100644 --- a/bittensor/btlogging/loggingmachine.py +++ b/bittensor/btlogging/loggingmachine.py @@ -171,15 +171,15 @@ def _create_file_handler(self, logfile: str): file_handler.setFormatter(self._file_formatter) file_handler.setLevel(stdlogging.TRACE) return file_handler - + def enable_third_party_loggers(self): for logger in all_loggers(): if logger.name == self._name: - continue + continue queue_handler = QueueHandler(self._queue) logger.addHandler(queue_handler) logger.setLevel(self._logger.level) - + def disable_third_party_loggers(self): # remove all handlers for logger in all_loggers(): @@ -323,7 +323,7 @@ def set_trace(self, on: bool = True): def get_level(self): return self._logger.level - + def check_config(self, config: bittensor.config): assert config.logging @@ -381,15 +381,15 @@ def config(cls): return bittensor.config(parser, args=[]) def __call__( - self, - config: bittensor.config = None, + self, + config: bittensor.config = None, debug: bool = None, trace: bool = None, record_log: bool = None, logging_dir: str = None, ): if config is not None: - cfg = copy.deepcopy(config) + cfg = copy.deepcopy(config) if debug is not None: cfg.debug = debug elif trace is not None: @@ -400,9 +400,6 @@ def __call__( cfg.logging_dir = logging_dir else: cfg = LoggingConfig( - debug=debug, - trace=trace, - record_log=record_log, - logging_dir=logging_dir + debug=debug, trace=trace, record_log=record_log, logging_dir=logging_dir ) self.set_config(cfg) From b5f0dce286074c91d475a3544cb9edc6892e2e98 Mon Sep 17 00:00:00 2001 From: e-gons <59700377+e-gons@users.noreply.github.com> Date: Sat, 23 Mar 2024 14:14:34 -0700 Subject: [PATCH 30/33] Update DEBUGGING.md Removed first line which looked like response from LLM --- contrib/DEBUGGING.md | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/contrib/DEBUGGING.md b/contrib/DEBUGGING.md index 42cf5b7029..093e3432bf 100644 --- a/contrib/DEBUGGING.md +++ b/contrib/DEBUGGING.md @@ -1,5 +1,3 @@ -Sure, here's a more detailed guide on debugging Bittensor, including some code examples from the Bittensor repository. - ## Installation First, make sure you have Bittensor installed correctly. There are three ways to install Bittensor: @@ -160,4 +158,4 @@ $ ag "query_subtensor" ... ``` -Remember, debugging involves a lot of trial and error. Don't be discouraged if things don't work right away. Keep trying different things, and don't hesitate to ask for help if you need it. \ No newline at end of file +Remember, debugging involves a lot of trial and error. Don't be discouraged if things don't work right away. Keep trying different things, and don't hesitate to ask for help if you need it. From ddfc62bd1676ed044cab684c34265cc50742d53b Mon Sep 17 00:00:00 2001 From: ifrit98 Date: Mon, 25 Mar 2024 16:34:44 +0000 Subject: [PATCH 31/33] fix install.sh display of btlci subcommands --- scripts/install.sh | 17 ++++++++--------- 1 file changed, 8 insertions(+), 9 deletions(-) diff --git a/scripts/install.sh b/scripts/install.sh index 7fce9f9186..5111d75afb 100755 --- a/scripts/install.sh +++ b/scripts/install.sh @@ -275,21 +275,20 @@ echo "" ohai "Extras:" echo "" echo "- Check your tao balance: " -echo " $ btcli overview" +echo " $ btcli wallet overview" echo "" echo "- Stake to your miners:" -echo " $ btcli stake" -echo " $ btcli unstake" +echo " $ btcli stake add" +echo " $ btcli stake remove" echo "" echo "- Create/list/register wallets" -echo " $ btcli new_coldkey" -echo " $ btcli new_hotkey" -echo " $ btcli list" -echo " $ btcli register --netuid 1" +echo " $ btcli w new_coldkey" +echo " $ btcli w new_hotkey" +echo " $ btcli w list" +echo " $ btcli s register" echo "" echo "- Use the Python API" -echo " $ python3" -echo " >> import bittensor" +echo " $ python3"echo " >> import bittensor" echo "" echo "- Join the discussion: " echo " ${tty_underline}https://discord.gg/3rUr6EcvbB${tty_reset}" From 913083a2d515e1341b9723328c0fcd1bbb6b919b Mon Sep 17 00:00:00 2001 From: ifrit98 Date: Mon, 25 Mar 2024 20:57:33 +0000 Subject: [PATCH 32/33] add version --- VERSION | 2 +- bittensor/__init__.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/VERSION b/VERSION index 6020dfc232..11946a9fd7 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -6.9.3 \ No newline at end of file +6.10.0 \ No newline at end of file diff --git a/bittensor/__init__.py b/bittensor/__init__.py index 63fd4b60b8..3a50f14358 100644 --- a/bittensor/__init__.py +++ b/bittensor/__init__.py @@ -27,7 +27,7 @@ nest_asyncio.apply() # Bittensor code and protocol version. -__version__ = "6.9.3" +__version__ = "6.10.0" version_split = __version__.split(".") __version_as_int__: int = ( From 4fed84442dee7fb424a58507e0533e615908fb17 Mon Sep 17 00:00:00 2001 From: ifrit98 Date: Mon, 25 Mar 2024 20:58:40 +0000 Subject: [PATCH 33/33] add changelog --- CHANGELOG.md | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index b61cbdff07..afbdb10e3d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,22 @@ # Changelog +## 6.10.0 / 2024-03-25 + +## What's Changed +* handle req args by parsing and raising by @ifrit98 in https://github.com/opentensor/bittensor/pull/1733 +* Replace wildcard imports with specific imports by @brueningf in https://github.com/opentensor/bittensor/pull/1724 +* Logging Refactor by @sepehr-opentensor in https://github.com/opentensor/bittensor/pull/1751 +* Update DEBUGGING.md by @e-gons in https://github.com/opentensor/bittensor/pull/1755 +* fix: nonce implementation by @GentikSolm in https://github.com/opentensor/bittensor/pull/1754 + +## New Contributors +* @sepehr-opentensor made their first contribution in https://github.com/opentensor/bittensor/pull/1751 +* @e-gons made their first contribution in https://github.com/opentensor/bittensor/pull/1755 +* @GentikSolm made their first contribution in https://github.com/opentensor/bittensor/pull/1754 + +**Full Changelog**: https://github.com/opentensor/bittensor/compare/v6.9.3...v6.10.0 + + ## 6.9.3 / 2024-03-12 ## What's Changed