Nucypher
/
nucypher
mirror of https://github.com/nucypher/nucypher.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

Merge pull request #3483 from derekpierre/logging 

Much Ado About Logging
pull/3486/head
Derek Pierre 2024-04-22 14:15:06 -04:00 committed by GitHub
parent c313ea790d 45d82f6699
commit 532745632b
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
7 changed files with 250 additions and 71 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
newsfragments/3483.bugfix.rst Normal file
View File

@ -0,0 +1,2 @@
Console logging was not using the correct log format, log levels were not adhered to for limiting log messages, and global log observers not correctly managed.
Improved the StdoutEmitter to better utilize the logger so that information is not lost.

1
newsfragments/3483.feature.rst Normal file
View File

@ -0,0 +1 @@
Add ``--json-logs/--no-json-logs`` CLI option to enabled/disable logging to a json log file; json logging is now disabled be default.

2
nucypher/blockchain/eth/interfaces.py
View File

@ -158,7 +158,6 @@ class BlockchainInterface:
@staticmethod
def __default_on_broadcast(tx: PendingTx):
# TODO review use of emitter - #3482
emitter = StdoutEmitter()
max_cost, max_price_gwei, tx_type = get_tx_cost_data(tx.params)
emitter.message(
@ -623,7 +622,6 @@ class BlockchainInterface:
#
# Broadcast
#
# TODO review use of emitter - #3482
emitter.message(
f"Broadcasting {transaction_name} {tx_type} Transaction ({max_cost} @ {max_price_gwei} gwei)",
color="yellow",

36
nucypher/cli/config.py
View File

@ -23,18 +23,21 @@ class GroupGeneralConfig:
sentry_endpoint = os.environ.get("NUCYPHER_SENTRY_DSN", NUCYPHER_SENTRY_ENDPOINT)
log_to_sentry = get_env_bool("NUCYPHER_SENTRY_LOGS", False)
log_to_file = get_env_bool("NUCYPHER_FILE_LOGS", True)
log_to_json_file = get_env_bool("NUCYPHER_JSON_LOGS", False)
def __init__(self,
json_ipc: bool,
verbose: bool,
quiet: bool,
no_logs: bool,
console_logs: bool,
file_logs: bool,
sentry_logs: bool,
log_level: bool,
debug: bool):
def __init__(
self,
json_ipc: bool,
verbose: bool,
quiet: bool,
no_logs: bool,
console_logs: bool,
file_logs: bool,
json_logs: bool,
sentry_logs: bool,
log_level: bool,
debug: bool,
):
self.log = Logger(self.__class__.__name__)
# Session Emitter for pre and post character control engagement.
@ -66,6 +69,8 @@ class GroupGeneralConfig:
# Defaults
if file_logs is None:
file_logs = self.log_to_file
if json_logs is None:
json_logs = self.log_to_json_file
if sentry_logs is None:
sentry_logs = self.log_to_sentry
@ -78,6 +83,7 @@ class GroupGeneralConfig:
if no_logs:
console_logs = False
file_logs = False
json_logs = False
sentry_logs = False
if json_ipc:
console_logs = False
@ -88,6 +94,7 @@ class GroupGeneralConfig:
GlobalLoggerSettings.start_console_logging()
if file_logs:
GlobalLoggerSettings.start_text_file_logging()
if json_logs:
GlobalLoggerSettings.start_json_file_logging()
if sentry_logs:
GlobalLoggerSettings.start_sentry_logging(self.sentry_endpoint)
@ -116,7 +123,12 @@ group_general_config = group_options(
file_logs=click.option(
'--file-logs/--no-file-logs',
help="Enable/disable logging to file. Defaults to NUCYPHER_FILE_LOGS, or to `--file-logs` if it is not set.",
help="Enable/disable logging to text file. Defaults to NUCYPHER_FILE_LOGS, or to `--file-logs` if it is not set.",
default=None,
),
json_logs=click.option(
"--json-logs/--no-json-logs",
help="Enable/disable logging to a json file. Defaults to NUCYPHER_JSON_LOGS, or to `--no-json-logs` if it is not set.",
default=None),
sentry_logs=click.option(

37
nucypher/utilities/emitters.py
View File

@ -1,33 +1,16 @@
import os
from functools import partial
from typing import Callable
import click
from nucypher.utilities.logging import Logger
def null_stream():
return open(os.devnull, 'w')
class StdoutEmitter:
class MethodNotFound(BaseException):
"""Cannot find interface method to handle request"""
transport_serializer = str
default_color = 'white'
# sys.stdout.write() TODO: doesn't work well with click_runner's output capture
default_sink_callable = partial(print, flush=True)
def __init__(self,
sink: Callable = None,
verbosity: int = 1):
self.name = self.__class__.__name__.lower()
self.sink = sink or self.default_sink_callable
self.verbosity = verbosity
self.log = Logger(self.name)
@ -41,7 +24,12 @@ class StdoutEmitter:
bold: bool = False,
verbosity: int = 1):
self.echo(message, color=color or self.default_color, bold=bold, verbosity=verbosity)
self.log.debug(message)
# these are application messages that are desired to be
# printed to stdout (with or w/o console logging); send to logger
if verbosity > 1:
self.log.debug(message)
else:
self.log.info(message)
def echo(self,
message: str = None,
@ -49,21 +37,18 @@ class StdoutEmitter:
bold: bool = False,
nl: bool = True,
verbosity: int = 0):
# these are user interactions; don't send to logger
if verbosity <= self.verbosity:
click.secho(message=message, fg=color or self.default_color, bold=bold, nl=nl)
def banner(self, banner):
# these are purely for banners; don't send to logger
if self.verbosity >= 1:
click.echo(banner)
def error(self, e):
e_str = str(e)
if self.verbosity >= 1:
e_str = str(e)
click.echo(message=e_str, color="red")
self.log.info(e_str)
def get_stream(self, verbosity: int = 0):
if verbosity <= self.verbosity:
return click.get_text_stream('stdout')
else:
return null_stream()
# some kind of error; send to logger
self.log.error(e_str)

90
nucypher/utilities/logging.py
View File

@ -1,16 +1,15 @@
import pathlib
import sys
from contextlib import contextmanager
from enum import Enum
from twisted.logger import (
FileLogObserver,
LogLevel,
formatEvent,
formatEventAsClassicLogText,
globalLogPublisher,
jsonFileLogObserver,
textFileLogObserver,
)
from twisted.logger import Logger as TwistedLogger
from twisted.python.logfile import LogFile
@ -69,58 +68,94 @@ class GlobalLoggerSettings:
log_level = LogLevel.levelWithName("info")
_json_ipc = False # TODO: Oh no... #1754
_observers = dict()
class LoggingType(Enum):
CONSOLE = "console"
TEXT = "text"
JSON = "json"
SENTRY = "sentry"
@classmethod
def set_log_level(cls, log_level_name):
cls.log_level = LogLevel.levelWithName(log_level_name)
@classmethod
def _stop_logging(cls, logging_type: LoggingType):
observer = cls._observers.pop(logging_type, None)
if observer:
globalLogPublisher.removeObserver(observer)
@classmethod
def _is_already_configured(cls, logging_type: LoggingType) -> bool:
return logging_type in cls._observers
@classmethod
def _start_logging(cls, logging_type: LoggingType):
if cls._is_already_configured(logging_type):
# no-op
return
if logging_type == cls.LoggingType.CONSOLE:
observer = textFileLogObserver(sys.stdout)
elif logging_type == cls.LoggingType.TEXT:
observer = get_text_file_observer()
elif logging_type == cls.LoggingType.JSON:
observer = get_json_file_observer()
else:
# sentry
observer = sentry_observer
cls._observers[logging_type] = observer
globalLogPublisher.addObserver(observer)
@classmethod
def start_console_logging(cls):
globalLogPublisher.addObserver(console_observer)
cls._start_logging(cls.LoggingType.CONSOLE)
@classmethod
def stop_console_logging(cls):
globalLogPublisher.removeObserver(console_observer)
@classmethod
@contextmanager
def pause_all_logging_while(cls):
former_observers = tuple(globalLogPublisher._observers)
for observer in former_observers:
globalLogPublisher.removeObserver(observer)
yield
for observer in former_observers:
globalLogPublisher.addObserver(observer)
cls._stop_logging(cls.LoggingType.CONSOLE)
@classmethod
def start_text_file_logging(cls):
globalLogPublisher.addObserver(get_text_file_observer())
cls._start_logging(cls.LoggingType.TEXT)
@classmethod
def stop_text_file_logging(cls):
globalLogPublisher.removeObserver(get_text_file_observer())
cls._stop_logging(cls.LoggingType.TEXT)
@classmethod
def start_json_file_logging(cls):
globalLogPublisher.addObserver(get_json_file_observer())
cls._start_logging(cls.LoggingType.JSON)
@classmethod
def stop_json_file_logging(cls):
globalLogPublisher.removeObserver(get_json_file_observer())
cls._stop_logging(cls.LoggingType.JSON)
@classmethod
def start_sentry_logging(cls, dsn: str):
_SentryInitGuard.init(dsn)
globalLogPublisher.addObserver(sentry_observer)
cls._start_logging(cls.LoggingType.SENTRY)
@classmethod
def stop_sentry_logging(cls):
globalLogPublisher.removeObserver(sentry_observer)
cls._stop_logging(cls.LoggingType.SENTRY)
@classmethod
@contextmanager
def pause_all_logging_while(cls):
all_former_observers = tuple(globalLogPublisher._observers)
former_global_observers = dict(cls._observers)
for observer in all_former_observers:
globalLogPublisher.removeObserver(observer)
cls._observers.clear()
def console_observer(event):
if event['log_level'] >= GlobalLoggerSettings.log_level:
print(formatEvent(event))
yield
cls._observers.clear()
for observer in all_former_observers:
globalLogPublisher.addObserver(observer)
cls._observers.update(former_global_observers)
class _SentryInitGuard:
@ -186,5 +221,6 @@ class Logger(TwistedLogger):
return escaped_string
def emit(self, level, format=None, **kwargs):
clean_format = self.escape_format_string(str(format))
super().emit(level=level, format=clean_format, **kwargs)
if level >= GlobalLoggerSettings.log_level:
clean_format = self.escape_format_string(str(format))
super().emit(level=level, format=clean_format, **kwargs)

153
tests/unit/test_logging.py
View File

@ -1,13 +1,19 @@
from functools import partial
from io import StringIO
from json.encoder import py_encode_basestring_ascii
from unittest import mock
import pytest
from twisted.logger import Logger as TwistedLogger
from twisted.logger import formatEvent, jsonFileLogObserver
from twisted.logger import (
LogLevel,
formatEvent,
globalLogPublisher,
jsonFileLogObserver,
)
from nucypher.utilities.logging import Logger
from nucypher.utilities.emitters import StdoutEmitter
from nucypher.utilities.logging import GlobalLoggerSettings, Logger
def naive_print_observer(event):
@ -146,3 +152,142 @@ def test_even_nucypher_json_logger_is_cool():
logged_event = file.getvalue()
assert '"log_level": {"name": "info"' in logged_event
assert f'"log_format": "{expected_processing(string)}"' in logged_event
def test_pause_all_logging_while():
# get state beforehand
former_global_observers = dict(GlobalLoggerSettings._observers)
former_registered_observers = list(globalLogPublisher._observers)
with GlobalLoggerSettings.pause_all_logging_while():
# within context manager
assert len(GlobalLoggerSettings._observers) == 0
assert len(globalLogPublisher._observers) == 0
# exited context manager
assert former_global_observers == GlobalLoggerSettings._observers
assert former_registered_observers == globalLogPublisher._observers
@pytest.mark.parametrize("global_log_level", LogLevel._enumerants.values())
def test_log_level_adhered_to(global_log_level):
old_log_level = GlobalLoggerSettings.log_level.name
try:
GlobalLoggerSettings.set_log_level(global_log_level.name)
received_events = []
def logger_observer(event):
received_events.append(event)
logger = Logger("test-logger")
logger.observer = logger_observer
message = "People without self-doubt should never put themselves in a position of complete power" # - Chuck Rhoades (Billions)
num_logged_events = 0
for level in LogLevel._enumerants.values():
# call logger.<level>(message)
getattr(logger, level.name)(message)
if level >= global_log_level:
num_logged_events += 1
# else not logged
assert len(received_events) == num_logged_events
finally:
GlobalLoggerSettings.set_log_level(old_log_level)
@pytest.mark.parametrize(
"start_logging_fn, stop_logging_fn, logging_type",
(
(
GlobalLoggerSettings.start_console_logging,
GlobalLoggerSettings.stop_console_logging,
GlobalLoggerSettings.LoggingType.CONSOLE,
),
(
GlobalLoggerSettings.start_text_file_logging,
GlobalLoggerSettings.stop_text_file_logging,
GlobalLoggerSettings.LoggingType.TEXT,
),
(
GlobalLoggerSettings.start_json_file_logging,
GlobalLoggerSettings.stop_json_file_logging,
GlobalLoggerSettings.LoggingType.JSON,
),
(
partial(GlobalLoggerSettings.start_sentry_logging, dsn="mock_dsn"),
GlobalLoggerSettings.stop_sentry_logging,
GlobalLoggerSettings.LoggingType.SENTRY,
),
),
)
@mock.patch("nucypher.utilities.logging.initialize_sentry", return_value=None)
def test_addition_removal_global_observers(
sentry_mock_init, start_logging_fn, stop_logging_fn, logging_type
):
with GlobalLoggerSettings.pause_all_logging_while():
# start logging
start_logging_fn()
assert len(globalLogPublisher._observers) == 1
assert len(GlobalLoggerSettings._observers) == 1
original_global_observer = GlobalLoggerSettings._observers[logging_type]
assert original_global_observer is not None
assert original_global_observer in globalLogPublisher._observers
# try starting again - noop
start_logging_fn()
assert len(globalLogPublisher._observers) == 1
assert original_global_observer in globalLogPublisher._observers
assert len(GlobalLoggerSettings._observers) == 1
assert GlobalLoggerSettings._observers[logging_type] == original_global_observer
# stop logging
stop_logging_fn()
assert len(globalLogPublisher._observers) == 0
assert len(GlobalLoggerSettings._observers) == 0
# try stopping again, when already stopped/removed - noop
stop_logging_fn()
def test_stdout_emitter_link_to_logging(mocker):
message = "Learn from the mistakes of others. You can’t live long enough to make them all yourself." # - Eleanor Roosevelt
emit_fn = mocker.Mock()
with mocker.patch("nucypher.utilities.logging.Logger.emit", side_effect=emit_fn):
call_count = 0
assert emit_fn.call_count == call_count
emitter = StdoutEmitter()
# message(...)
for verbosity in [0, 1, 2]:
emitter.message(message=message, verbosity=verbosity)
call_count += 1
assert emit_fn.call_count == call_count
if verbosity < 2:
emit_fn.assert_called_with(LogLevel.info, message)
else:
emit_fn.assert_called_with(LogLevel.debug, message)
# echo(...)
for verbosity in [0, 1, 2]:
emitter.echo(message=message, verbosity=verbosity)
assert (
emit_fn.call_count == call_count
), "user interactions so no change in call count"
# error(...)
exception = ValueError(message)
emitter.error(exception)
call_count += 1
assert emit_fn.call_count == call_count
emit_fn.assert_called_with(LogLevel.error, str(exception))
# banner(...)
emitter.banner(banner=message)
assert (
emit_fn.call_count == call_count
), "just a banner so no change in call count"