diff --git a/lbry/lbry/extras/cli.py b/lbry/lbry/extras/cli.py index 07b2298a0..4403832af 100644 --- a/lbry/lbry/extras/cli.py +++ b/lbry/lbry/extras/cli.py @@ -7,10 +7,10 @@ import asyncio import argparse import logging import logging.handlers -from docopt import docopt import aiohttp from aiohttp.web import GracefulExit +from docopt import docopt from lbry import __version__ as lbrynet_version from lbry.extras.daemon.loggly_handler import get_loggly_handler @@ -142,7 +142,7 @@ class ArgumentParser(argparse.ArgumentParser): def error(self, message): self.print_help(argparse._sys.stderr) - self.exit(2, '\n'+message+'\n') + self.exit(2, f"\n{message}\n") class HelpFormatter(argparse.HelpFormatter): @@ -223,11 +223,9 @@ def ensure_directory_exists(path: str): LOG_MODULES = ('lbry', 'torba', 'aioupnp') -def setup_logging(args: argparse.Namespace, conf: Config, logger: logging.Logger): +def setup_logging(logger: logging.Logger, args: argparse.Namespace, conf: Config): default_formatter = logging.Formatter("%(asctime)s %(levelname)-8s %(name)s:%(lineno)d: %(message)s") - file_handler = logging.handlers.RotatingFileHandler( - conf.log_file_path, maxBytes=2097152, backupCount=5 - ) + file_handler = logging.handlers.RotatingFileHandler(conf.log_file_path, maxBytes=2097152, backupCount=5) file_handler.setFormatter(default_formatter) for module_name in LOG_MODULES: logger.getChild(module_name).addHandler(file_handler) @@ -259,7 +257,7 @@ def run_daemon(args: argparse.Namespace, conf: Config): loop = asyncio.get_event_loop() if args.verbose is not None: loop.set_debug(True) - setup_logging(args, conf, logging.getLogger()) + setup_logging(logging.getLogger(), args, conf) daemon = Daemon(conf) def __exit(): diff --git a/lbry/lbry/extras/daemon/loggly_handler.py b/lbry/lbry/extras/daemon/loggly_handler.py index f59e54baa..505e83d5f 100644 --- a/lbry/lbry/extras/daemon/loggly_handler.py +++ b/lbry/lbry/extras/daemon/loggly_handler.py @@ -67,6 +67,10 @@ class HTTPSLogglyHandler(logging.Handler): def emit(self, record): asyncio.ensure_future(self._emit(record)) + def close(self): + super().close() + asyncio.create_task(self._session.close()) + def get_loggly_handler(): handler = HTTPSLogglyHandler(LOGGLY_TOKEN) diff --git a/lbry/tests/unit/test_cli.py b/lbry/tests/unit/test_cli.py index 7a4cb54e8..39fe0ee3a 100644 --- a/lbry/tests/unit/test_cli.py +++ b/lbry/tests/unit/test_cli.py @@ -1,7 +1,12 @@ +import os +import tempfile +import shutil import contextlib import logging from io import StringIO from unittest import TestCase +from types import SimpleNamespace +from contextlib import asynccontextmanager import docopt from torba.testcase import AsyncioTestCase @@ -9,39 +14,92 @@ from torba.testcase import AsyncioTestCase from lbry.extras.cli import normalize_value, main, setup_logging from lbry.extras.system_info import get_platform from lbry.extras.daemon.Daemon import Daemon +from lbry.extras.daemon.loggly_handler import HTTPSLogglyHandler from lbry.conf import Config from lbry.extras import cli +@asynccontextmanager +async def get_logger(argv, **conf_options): + # loggly requires loop, so we do this in async function + + logger = logging.getLogger('test-root-logger') + temp_dir = tempfile.mkdtemp() + temp_config = os.path.join(temp_dir, 'settings.yml') + + try: + # create a config (to be loaded on startup) + _conf = Config.create_from_arguments(SimpleNamespace(config=temp_config)) + with _conf.update_config(): + for opt_name, opt_value in conf_options.items(): + setattr(_conf, opt_name, opt_value) + + # do what happens on startup + argv.extend(['--data-dir', temp_dir]) + argv.extend(['--wallet-dir', temp_dir]) + argv.extend(['--config', temp_config]) + parser = cli.get_argument_parser() + args, command_args = parser.parse_known_args(argv) + conf: Config = Config.create_from_arguments(args) + setup_logging(logger, args, conf) + yield logger + + finally: + shutil.rmtree(temp_dir, ignore_errors=True) + for mod in cli.LOG_MODULES: + log = logger.getChild(mod) + log.setLevel(logging.NOTSET) + while log.handlers: + h = log.handlers[0] + log.removeHandler(log.handlers[0]) + h.close() + + class CLILoggingTest(AsyncioTestCase): - async def test_setup_logging(self): - # test needs to be async to avoid warnings from loggly + async def test_verbose_logging(self): + async with get_logger(["start", "--quiet"], share_usage_data=False) as log: + log = log.getChild("lbry") + self.assertTrue(log.isEnabledFor(logging.INFO)) + self.assertFalse(log.isEnabledFor(logging.DEBUG)) + self.assertFalse(log.isEnabledFor(logging.DEBUG)) + self.assertEqual(len(log.handlers), 1) + self.assertIsInstance(log.handlers[0], logging.handlers.RotatingFileHandler) - def setup(argv): - parser = cli.get_argument_parser() - args, command_args = parser.parse_known_args(argv) - conf = Config.create_from_arguments(args) - conf.data_dir = '/tmp' - setup_logging(args, conf, logger) + async with get_logger(["start", "--verbose"]) as log: + self.assertTrue(log.getChild("lbry").isEnabledFor(logging.DEBUG)) + self.assertTrue(log.getChild("lbry").isEnabledFor(logging.INFO)) + self.assertFalse(log.getChild("torba").isEnabledFor(logging.DEBUG)) - logger = logging.getLogger('test_logger') + async with get_logger(["start", "--verbose", "lbry.extras", "lbry.wallet", "torba.client"]) as log: + self.assertTrue(log.getChild("lbry.extras").isEnabledFor(logging.DEBUG)) + self.assertTrue(log.getChild("lbry.wallet").isEnabledFor(logging.DEBUG)) + self.assertTrue(log.getChild("torba.client").isEnabledFor(logging.DEBUG)) + self.assertFalse(log.getChild("lbry").isEnabledFor(logging.DEBUG)) + self.assertFalse(log.getChild("torba").isEnabledFor(logging.DEBUG)) - setup(["start"]) - self.assertTrue(logger.getChild("lbry").isEnabledFor(logging.INFO)) - self.assertFalse(logger.getChild("lbry").isEnabledFor(logging.DEBUG)) + async def test_loggly(self): + async with get_logger(["start"], share_usage_data=False) as log: + self.assertEqual(len(log.getChild("lbry").handlers), 2) # file and console + async with get_logger(["start"]) as log: # default share_usage_data=True + log = log.getChild("lbry") + self.assertEqual(len(log.handlers), 3) + self.assertIsInstance(log.handlers[2], HTTPSLogglyHandler) + async with get_logger(["start"], share_usage_data=True) as log: # explicit share_usage_data=True + log = log.getChild("lbry") + self.assertEqual(len(log.handlers), 3) + self.assertIsInstance(log.handlers[2], HTTPSLogglyHandler) - setup(["start", "--verbose"]) - self.assertTrue(logger.getChild("lbry").isEnabledFor(logging.DEBUG)) - self.assertTrue(logger.getChild("lbry").isEnabledFor(logging.INFO)) - self.assertFalse(logger.getChild("torba").isEnabledFor(logging.DEBUG)) - - setup(["start", "--verbose", "lbry.extras", "lbry.wallet", "torba.client"]) - self.assertTrue(logger.getChild("lbry.extras").isEnabledFor(logging.DEBUG)) - self.assertTrue(logger.getChild("lbry.wallet").isEnabledFor(logging.DEBUG)) - self.assertTrue(logger.getChild("torba.client").isEnabledFor(logging.DEBUG)) - self.assertFalse(logger.getChild("lbry").isEnabledFor(logging.DEBUG)) - self.assertFalse(logger.getChild("torba").isEnabledFor(logging.DEBUG)) + async def test_quiet(self): + async with get_logger(["start"]) as log: # default is loud + log = log.getChild("lbry") + self.assertEqual(len(log.handlers), 3) + self.assertIs(type(log.handlers[1]), logging.StreamHandler) + async with get_logger(["start", "--quiet"]) as log: + log = log.getChild("lbry") + self.assertEqual(len(log.handlers), 2) + self.assertIsNot(type(log.handlers[0]), logging.StreamHandler) + self.assertIsNot(type(log.handlers[1]), logging.StreamHandler) class CLITest(AsyncioTestCase):