From 921b39dbfeb73b28cf6bf2c328ce749e168bd229 Mon Sep 17 00:00:00 2001 From: "Mr. Outis" Date: Tue, 2 Apr 2019 20:56:31 -0600 Subject: [PATCH] tests: use pytest caplog instead of custom mock Close #1753 --- dvc/command/diff.py | 8 +- dvc/command/remote.py | 1 + dvc/logger.py | 36 +++---- dvc/progress.py | 15 --- dvc/prompt.py | 13 +-- tests/basic_env.py | 12 ++- tests/test_add.py | 34 +++--- tests/test_checkout.py | 33 +++--- tests/test_data_cloud.py | 70 +++++------- tests/test_import.py | 38 ++++--- tests/test_logger.py | 190 -------------------------------- tests/test_metrics.py | 209 +++++++++++++++++------------------- tests/test_repro.py | 32 +++--- tests/test_tag.py | 74 ++++++------- tests/test_utils.py | 11 ++ tests/unit/test_logger.py | 149 +++++++++++++++++++++++++ tests/unit/test_progress.py | 25 +---- tests/utils/__init__.py | 13 --- tests/utils/logger.py | 35 ------ 19 files changed, 417 insertions(+), 581 deletions(-) delete mode 100644 tests/test_logger.py create mode 100644 tests/unit/test_logger.py delete mode 100644 tests/utils/logger.py diff --git a/dvc/command/diff.py b/dvc/command/diff.py index 2eb73bd05..ca5245d71 100644 --- a/dvc/command/diff.py +++ b/dvc/command/diff.py @@ -2,15 +2,17 @@ from __future__ import unicode_literals import humanize import inflect +import logging - -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase from dvc.utils.collections import compact import dvc.repo.diff as diff +logger = logging.getLogger(__name__) + + class CmdDiff(CmdBase): def _print_size(self, size): if size < 0: @@ -113,7 +115,7 @@ class CmdDiff(CmdBase): compact([self.args.target, self.args.a_ref, self.args.b_ref]) ) msg = msg.format(args) - logger.error(msg) + logger.exception(msg) return 1 return 0 diff --git a/dvc/command/remote.py b/dvc/command/remote.py index 1dee14949..f69a7ba6e 100644 --- a/dvc/command/remote.py +++ b/dvc/command/remote.py @@ -5,6 +5,7 @@ import os import re import logging +from dvc.command.base import append_doc_link, fix_subparsers from dvc.command.config import CmdConfig from dvc.config import Config diff --git a/dvc/logger.py b/dvc/logger.py index d6ec9fdd0..0f428e61d 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -2,7 +2,7 @@ from __future__ import unicode_literals -from dvc.utils.compat import str +from dvc.utils.compat import str, StringIO import logging import logging.handlers @@ -47,17 +47,11 @@ class ColorFormatter(logging.Formatter): ) def format(self, record): - # Might result in messy terminal if we allow this in DEBUG records, - # because analytics is logging on a separate thread, that might not - # be using the same instance of `progress`. - if record.levelname != "DEBUG": - self._progress_aware() - if record.levelname == "INFO": return record.msg if record.levelname == "ERROR" or record.levelname == "CRITICAL": - exception, stack_trace = self._parse_exc() + exception, stack_trace = self._parse_exc(record.exc_info) return ( "{color}{levelname}{nc}: {description}" @@ -82,6 +76,8 @@ class ColorFormatter(logging.Formatter): ) def _description(self, message, exception): + description = "" + if exception and message: description = "{message} - {exception}" elif exception: @@ -91,29 +87,33 @@ class ColorFormatter(logging.Formatter): return description.format(message=message, exception=exception) - def _walk_exc(self, exc): + def _walk_exc(self, exc_info): import traceback + buffer = StringIO() + + traceback.print_exception(*exc_info, file=buffer) + + exc = exc_info[1] + tb = buffer.getvalue() + exc_list = [str(exc)] - tb_list = [traceback.format_exc()] + tb_list = [tb] # NOTE: parsing chained exceptions. See dvc/exceptions.py for more info - while hasattr(exc, "cause") and exc.cause is not None: + while hasattr(exc, "cause") and exc.cause: exc_list.append(str(exc.cause)) - if hasattr(exc, "cause_tb") and exc.cause_tb is not None: + if hasattr(exc, "cause_tb") and exc.cause_tb: tb_list.insert(0, str(exc.cause_tb)) exc = exc.cause return exc_list, tb_list - def _parse_exc(self): - import sys - - exc = sys.exc_info()[1] - if not exc: + def _parse_exc(self, exc_info): + if not exc_info: return (None, "") - exc_list, tb_list = self._walk_exc(exc) + exc_list, tb_list = self._walk_exc(exc_info) exception = ": ".join(exc_list) diff --git a/dvc/progress.py b/dvc/progress.py index 3e247623e..ea0faa2ca 100644 --- a/dvc/progress.py +++ b/dvc/progress.py @@ -127,21 +127,6 @@ class Progress(object): self._lock.release() -def progress_aware(f): - """ Decorator to add a new line if progress bar hasn't finished """ - from functools import wraps - - @wraps(f) - def wrapper(*args, **kwargs): - if not progress.is_finished: - progress._print() - progress.clearln() - - return f(*args, **kwargs) - - return wrapper - - class ProgressCallback(object): def __init__(self, total): self.total = total diff --git a/dvc/prompt.py b/dvc/prompt.py index b44ef40de..c4cad9fb3 100644 --- a/dvc/prompt.py +++ b/dvc/prompt.py @@ -4,12 +4,15 @@ from __future__ import unicode_literals from __future__ import print_function import sys +import logging from getpass import getpass -from dvc.progress import progress_aware from dvc.utils.compat import input +logger = logging.getLogger(__name__) + + def _ask(prompt, limited_to=None): if not sys.stdout.isatty(): return None @@ -26,13 +29,12 @@ def _ask(prompt, limited_to=None): if answer in limited_to: return answer - print( + logger.info( "Your response must be one of: {options}. " "Please try again.".format(options=limited_to) ) -@progress_aware def confirm(statement): """Ask the user for confirmation about the specified statement. @@ -47,7 +49,6 @@ def confirm(statement): return answer and answer.startswith("y") -@progress_aware def password(statement): """Ask the user for a password. @@ -57,5 +58,5 @@ def password(statement): Returns: str: password entered by the user. """ - prompt = "{statement}: ".format(statement=statement) - return getpass(prompt) + logger.info("{statement}: ".format(statement=statement)) + return getpass("") diff --git a/tests/basic_env.py b/tests/basic_env.py index 340c8fb6a..0198dc7f0 100644 --- a/tests/basic_env.py +++ b/tests/basic_env.py @@ -6,17 +6,21 @@ import os import shutil import uuid import tempfile +import logging from git import Repo from git.exc import GitCommandNotFound from unittest import TestCase +import pytest -import dvc.logger as logger from dvc.command.remote import CmdRemoteAdd from dvc.repo import Repo as DvcRepo from dvc.utils.compat import open, str +logger = logging.getLogger("dvc") + + class TestDirFixture(object): GCP_CREDS_FILE = os.path.abspath( os.path.join("scripts", "ci", "gcp-creds.json") @@ -139,7 +143,7 @@ class TestDvcFixture(TestGitFixture): super(TestDvcFixture, self).setUp() self.dvc = DvcRepo.init(self._root_dir) self.dvc.scm.commit("init dvc") - logger.be_verbose() + logger.setLevel("DEBUG") class TestDvcGitInitializedFixture(TestDvcFixture): @@ -219,6 +223,10 @@ class TestDvc(TestDvcFixture, TestCase): TestDvcFixture.__init__(self, root_dir) TestCase.__init__(self, methodName) + @pytest.fixture(autouse=True) + def inject_fixtures(self, caplog): + self._caplog = caplog + class TestDvcPkg(TestDvcFixture, TestCase): GIT_PKG = "git_pkg" diff --git a/tests/test_add.py b/tests/test_add.py index cce7e260f..1649db7ed 100644 --- a/tests/test_add.py +++ b/tests/test_add.py @@ -8,7 +8,6 @@ import shutil import filecmp import posixpath -from dvc.logger import logger from dvc.system import System from mock import patch @@ -20,8 +19,7 @@ from dvc.output.base import OutputAlreadyTrackedError from dvc.repo import Repo as DvcRepo from tests.basic_env import TestDvc -from tests.utils import spy, reset_logger_error_output, get_gitignore_content -from tests.utils.logger import MockLoggerHandlers, ConsoleFontColorsRemover +from tests.utils import spy, get_gitignore_content class TestAdd(TestDvc): @@ -409,26 +407,26 @@ class TestShouldPlaceStageInDataDirIfRepositoryBelowSymlink(TestDvc): class TestShouldThrowProperExceptionOnCorruptedStageFile(TestDvc): def test(self): - with MockLoggerHandlers(logger), ConsoleFontColorsRemover(): - reset_logger_error_output() + ret = main(["add", self.FOO]) + assert 0 == ret - ret = main(["add", self.FOO]) - self.assertEqual(0, ret) + foo_stage = os.path.relpath(self.FOO + Stage.STAGE_FILE_SUFFIX) - foo_stage = os.path.relpath(self.FOO + Stage.STAGE_FILE_SUFFIX) + # corrupt stage file + with open(foo_stage, "a+") as file: + file.write("this will break yaml file structure") - # corrupt stage file - with open(foo_stage, "a+") as file: - file.write("this will break yaml file structure") + self._caplog.clear() - ret = main(["add", self.BAR]) - self.assertEqual(1, ret) + ret = main(["add", self.BAR]) + assert 1 == ret - self.assertIn( - "unable to read stage file: {} " - "YAML file structure is corrupted".format(foo_stage), - logger.handlers[1].stream.getvalue(), - ) + expected_error = ( + "unable to read stage file: {} " + "YAML file structure is corrupted".format(foo_stage) + ) + + assert expected_error in self._caplog.text class TestAddFilename(TestDvc): diff --git a/tests/test_checkout.py b/tests/test_checkout.py index 852223da1..e263c1938 100644 --- a/tests/test_checkout.py +++ b/tests/test_checkout.py @@ -6,8 +6,8 @@ import yaml import shutil import filecmp import collections +import logging -from dvc.logger import logger from dvc.main import main from dvc import progress from dvc.repo import Repo as DvcRepo @@ -25,7 +25,9 @@ from dvc.exceptions import ( ) from mock import patch -from tests.utils.logger import MockLoggerHandlers, ConsoleFontColorsRemover + + +logger = logging.getLogger("dvc") class TestCheckout(TestRepro): @@ -404,14 +406,22 @@ class TestCheckoutShouldHaveSelfClearingProgressBar(TestDvc): self._prepare_repo() def test(self): - self._checkout_and_intercept_std_output() + with self._caplog.at_level(logging.INFO, logger="dvc"), patch.object( + sys, "stdout" + ) as stdout_mock: + self.stdout_mock = logger.handlers[0].stream = stdout_mock + + ret = main(["checkout"]) + self.assertEqual(0, ret) stdout_calls = self.stdout_mock.method_calls write_calls = self.filter_out_non_write_calls(stdout_calls) write_calls = self.filter_out_empty_write_calls(write_calls) self.write_args = [w_c[1][0] for w_c in write_calls] - progress_bars = self.get_progress_bars() + pattern = re.compile(".*\\[.{30}\\].*%.*") + progress_bars = [arg for arg in self.write_args if pattern.match(arg)] + update_bars = progress_bars[:-1] finish_bar = progress_bars[-1] @@ -466,21 +476,6 @@ class TestCheckoutShouldHaveSelfClearingProgressBar(TestDvc): os.unlink(self.FOO) os.unlink(self.BAR) - def _checkout_and_intercept_std_output(self): - with MockLoggerHandlers( - logger - ), ConsoleFontColorsRemover(), patch.object( - sys, "stdout" - ) as stdout_mock: - self.stdout_mock = logger.handlers[0].stream = stdout_mock - - ret = main(["checkout"]) - self.assertEqual(0, ret) - - def get_progress_bars(self): - pattern = re.compile(".*\\[.{30}\\].*%.*") - return [arg for arg in self.write_args if pattern.match(arg)] - def assertCaretReturnFollowsEach(self, update_bars): for update_bar in update_bars: diff --git a/tests/test_data_cloud.py b/tests/test_data_cloud.py index e8637defa..b3f49828e 100644 --- a/tests/test_data_cloud.py +++ b/tests/test_data_cloud.py @@ -8,12 +8,11 @@ import getpass import platform import yaml import copy +import logging from dvc.state import State from mock import patch -from tests.utils.logger import MockLoggerHandlers, ConsoleFontColorsRemover -from dvc.logger import logger from dvc.utils.compat import str from dvc.main import main from dvc.config import Config @@ -31,11 +30,7 @@ from dvc.remote.base import STATUS_OK, STATUS_NEW, STATUS_DELETED from dvc.utils import file_md5, load_stage_file from tests.basic_env import TestDvc -from tests.utils import ( - spy, - reset_logger_standard_output, - reset_logger_error_output, -) +from tests.utils import spy TEST_REMOTE = "upstream" @@ -637,20 +632,19 @@ class TestWarnOnOutdatedStage(TestDvc): with open(stage_file_path, "w") as stage_file: yaml.dump(content, stage_file) - with MockLoggerHandlers(logger): - reset_logger_standard_output() + with self._caplog.at_level(logging.WARNING, logger="dvc"): + self._caplog.clear() self.main(["status", "-c"]) - self.assertIn( - "Warning: Output 'bar'(Stage: 'bar.dvc') is " - "missing version info. Cache for it will not be " - "collected. Use dvc repro to get your pipeline up to " - "date.", - logger.handlers[0].stream.getvalue(), + expected_warning = ( + "Output 'bar'(Stage: 'bar.dvc') is missing version info." + " Cache for it will not be collected." + " Use dvc repro to get your pipeline up to date." ) + assert expected_warning in self._caplog.text + def test(self): - with ConsoleFontColorsRemover(): - self._test() + self._test() class TestRecursiveSyncOperations(TestDataCloudBase): @@ -783,33 +777,21 @@ class TestShouldWarnOnNoChecksumInLocalAndRemoteCache(TestDvc): self.FOO, checksum_foo ) - def stderr_contains_message(self): - self.assertIn( - self.message_header, logger.handlers[1].stream.getvalue() - ) - self.assertIn( - self.message_foo_part, logger.handlers[1].stream.getvalue() - ) - self.assertIn( - self.message_bar_part, logger.handlers[1].stream.getvalue() - ) - def test(self): - with ConsoleFontColorsRemover(), MockLoggerHandlers(logger): - reset_logger_error_output() + self._caplog.clear() + main(["push"]) + assert self.message_header in self._caplog.text + assert self.message_foo_part in self._caplog.text + assert self.message_bar_part in self._caplog.text - ret = main(["push"]) - self.assertEqual(ret, 0) - self.stderr_contains_message() + self._caplog.clear() + main(["pull"]) + assert self.message_header in self._caplog.text + assert self.message_foo_part in self._caplog.text + assert self.message_bar_part in self._caplog.text - reset_logger_error_output() - - ret = main(["pull", "-f"]) - self.assertEqual(ret, 0) - self.stderr_contains_message() - - reset_logger_error_output() - - ret = main(["status", "-c"]) - self.assertEqual(ret, 0) - self.stderr_contains_message() + self._caplog.clear() + main(["status", "-c"]) + assert self.message_header in self._caplog.text + assert self.message_foo_part in self._caplog.text + assert self.message_bar_part in self._caplog.text diff --git a/tests/test_import.py b/tests/test_import.py index 82ebb3d66..8d770cacd 100644 --- a/tests/test_import.py +++ b/tests/test_import.py @@ -3,17 +3,16 @@ import dvc from dvc.utils.compat import str import os +import logging from uuid import uuid4 -from dvc import logger from dvc.utils.compat import urljoin from dvc.exceptions import DvcException from dvc.main import main from mock import patch, mock_open, call from tests.basic_env import TestDvc -from tests.utils import reset_logger_error_output, spy +from tests.utils import spy from tests.utils.httpd import StaticFileServer -from tests.utils.logger import MockLoggerHandlers, ConsoleFontColorsRemover class TestCmdImport(TestDvc): @@ -46,29 +45,28 @@ class TestDefaultOutput(TestDvc): class TestFailedImportMessage(TestDvc): - def test(self): - with ConsoleFontColorsRemover(): - self._test() - @patch("dvc.command.imp.urlparse") - def _test(self, imp_urlparse_patch): - with MockLoggerHandlers(logger.logger): - reset_logger_error_output() - page_address = "http://somesite.com/file_name" + def test(self, imp_urlparse_patch): + page_address = "http://somesite.com/file_name" - def dvc_exception(*args, **kwargs): - raise DvcException("message") + def dvc_exception(*args, **kwargs): + raise DvcException("message") - imp_urlparse_patch.side_effect = dvc_exception + imp_urlparse_patch.side_effect = dvc_exception + + self._caplog.clear() + + with self._caplog.at_level(logging.ERROR, logger="dvc"): main(["import", page_address]) - self.assertIn( - "Error: failed to import " - "http://somesite.com/file_name. You could also try " - "downloading it manually and adding it with `dvc add` " - "command.", - logger.logger.handlers[1].stream.getvalue(), + + expected_error = ( + "failed to import http://somesite.com/file_name." + " You could also try downloading it manually and" + " adding it with `dvc add` command." ) + assert expected_error in self._caplog.text + class TestInterruptedDownload(TestDvc): @property diff --git a/tests/test_logger.py b/tests/test_logger.py deleted file mode 100644 index 72a3ef21a..000000000 --- a/tests/test_logger.py +++ /dev/null @@ -1,190 +0,0 @@ -import traceback -from unittest import TestCase - -import logging -import dvc.logger as logger -from dvc.command.base import CmdBase -from dvc.exceptions import DvcException -from tests.utils import reset_logger_error_output, reset_logger_standard_output -from tests.utils.logger import ConsoleFontColorsRemover - - -class TestLogger(TestCase): - handlers = logger.logger.handlers - - def setUp(self): - logger.logger.handlers = [ - logger.logging.StreamHandler(), - logger.logging.StreamHandler(), - ] - reset_logger_standard_output() - reset_logger_error_output() - logger.set_default_level() - - self.consoleColorRemover = ConsoleFontColorsRemover() - self.consoleColorRemover.__enter__() - - def tearDown(self): - logger.logger.handlers = self.handlers - logger.be_verbose() - self.consoleColorRemover.__exit__() - - @property - def stdout(self): - return logger.logger.handlers[0].stream.getvalue() - - @property - def stderr(self): - return logger.logger.handlers[1].stream.getvalue() - - def test_info(self): - logger.info("message") - - self.assertEqual(self.stdout, "message\n") - - def test_debug(self): - with logger.verbose(): - logger.debug("message") - - self.assertEqual(self.stdout, "Debug: message\n") - - def test_warning(self): - logger.warning("message") - - self.assertEqual(self.stdout, "Warning: message\n") - - def test_error(self): - logger.error("message") - - output = ( - "Error: message\n" - "\n" - "Having any troubles? Hit us up at https://dvc.org/support," - " we are always happy to help!\n" - ) - - self.assertEqual(self.stderr, output) - - def test_error_with_exception(self): - try: - raise Exception("exception description") - except Exception: - logger.error("") - - output = ( - "Error: exception description\n" - "\n" - "Having any troubles? Hit us up at https://dvc.org/support," - " we are always happy to help!\n" - ) - - self.assertEqual(self.stderr, output) - - def test_error_with_exception_and_message(self): - try: - raise Exception("exception description") - except Exception: - logger.error("message") - - output = ( - "Error: message - exception description\n" - "\n" - "Having any troubles? Hit us up at https://dvc.org/support," - " we are always happy to help!\n" - ) - - self.assertEqual(self.stderr, output) - - def test_error_with_chained_exception_and_message(self): - try: - raise DvcException("exception", cause=Exception("cause")) - except Exception: - logger.error("message") - - output = ( - "Error: message - exception: cause\n" - "\n" - "Having any troubles? Hit us up at https://dvc.org/support," - " we are always happy to help!\n" - ) - - self.assertEqual(self.stderr, output) - - def test_traceback(self): - stack_trace1 = "stack_trace1\n" - stack_trace2 = "stack_trace2\n" - try: - exc1 = Exception("exception1") - exc2 = DvcException("exception2", cause=exc1) - exc2.cause_tb = stack_trace1 - exc3 = DvcException("exception3", cause=exc2) - exc3.cause_tb = stack_trace2 - raise exc3 - except Exception: - stack_trace3 = traceback.format_exc() - with logger.verbose(): - logger.error("message") - - output = ( - "Error: message - exception3: exception2: exception1\n" - "{line}\n" - "{stack_trace1}" - "\n" - "{stack_trace2}" - "\n" - "{stack_trace3}" - "{line}\n" - "\n" - "Having any troubles? Hit us up at https://dvc.org/support," - " we are always happy to help!\n" - ).format( - line="-" * 60, - stack_trace1=stack_trace1, - stack_trace2=stack_trace2, - stack_trace3=stack_trace3, - ) - - self.assertEqual(self.stderr, output) - - def test_box(self): - logger.box("message") - - output = ( - "+-----------------+\n" - "| |\n" - "| message |\n" - "| |\n" - "+-----------------+\n" - "\n" - ) - - self.assertEqual(self.stdout, output) - - def test_level(self): - self.assertEqual(logger.level(), logging.INFO) - - def test_is_verbose(self): - self.assertFalse(logger.is_verbose()) - - with logger.verbose(): - self.assertTrue(logger.is_verbose()) - - def test_is_quiet(self): - self.assertFalse(logger.is_quiet()) - - with logger.quiet(): - self.assertFalse(logger.is_verbose()) - - def test_cli(self): - class A(object): - quiet = True - verbose = False - - args = A() - CmdBase.set_loglevel(args) - self.assertEqual(logger.logger.getEffectiveLevel(), logging.CRITICAL) - - args.quiet = False - args.verbose = True - CmdBase.set_loglevel(args) - self.assertEqual(logger.logger.getEffectiveLevel(), logging.DEBUG) diff --git a/tests/test_metrics.py b/tests/test_metrics.py index bfa34366a..90370264a 100644 --- a/tests/test_metrics.py +++ b/tests/test_metrics.py @@ -1,16 +1,13 @@ # -*- coding: utf-8 -*- import os import json +import logging from dvc.repo import Repo as DvcRepo from dvc.main import main from dvc.exceptions import DvcException, BadMetricError, NoMetricsError from tests.basic_env import TestDvc -import dvc.logger as logger -from tests.utils import reset_logger_error_output, reset_logger_standard_output -from tests.utils.logger import MockLoggerHandlers - class TestMetrics(TestDvc): def setUp(self): @@ -225,61 +222,62 @@ class TestMetrics(TestDvc): self.dvc.metrics.modify("metrics.tsv", typ="tsv") self.dvc.metrics.modify("metrics.json", typ="json") - with MockLoggerHandlers(logger.logger): - reset_logger_standard_output() + self._caplog.clear() + with self._caplog.at_level(logging.INFO, logger="dvc"): ret = main(["metrics", "show"]) self.assertEqual(ret, 0) - expected_csv = ( - u"\tmetrics.csv:\n" - u"\t\tvalor_mse desviación_mse data_set \n" - u"\t\t0.421601 0.173461 entrenamiento \n" - u"\t\t0.67528 0.289545 pruebas \n" - u"\t\t0.671502 0.297848 validación" - ) + expected_csv = ( + u"\tmetrics.csv:\n" + u"\t\tvalor_mse desviación_mse data_set \n" + u"\t\t0.421601 0.173461 entrenamiento \n" + u"\t\t0.67528 0.289545 pruebas \n" + u"\t\t0.671502 0.297848 validación" + ) - expected_tsv = ( - "\tmetrics.tsv:\n" - "\t\tvalue_mse deviation_mse data_set \n" - "\t\t0.421601 0.173461 train \n" - "\t\t0.67528 0.289545 test\\ning \n" - "\t\t0.671502 0.297848 validation" - ) + expected_tsv = ( + "\tmetrics.tsv:\n" + "\t\tvalue_mse deviation_mse data_set \n" + "\t\t0.421601 0.173461 train \n" + "\t\t0.67528 0.289545 test\\ning \n" + "\t\t0.671502 0.297848 validation" + ) - expected_txt = ( - "\tmetrics.txt:\n" - "\t\tROC_AUC: 0.64\n" - "\t\tKS: 78.9999999996\n" - "\t\tF_SCORE: 77\n" - ) + expected_txt = ( + "\tmetrics.txt:\n" + "\t\tROC_AUC: 0.64\n" + "\t\tKS: 78.9999999996\n" + "\t\tF_SCORE: 77" + ) - expected_json = ( - "\tmetrics.json:\n" - "\t\t{\n" - '\t\t "data_set": [\n' - '\t\t "train",\n' - '\t\t "testing",\n' - '\t\t "validation"\n' - "\t\t ],\n" - '\t\t "deviation_mse": [\n' - '\t\t "0.173461",\n' - '\t\t "0.289545",\n' - '\t\t "0.297848"\n' - "\t\t ],\n" - '\t\t "value_mse": [\n' - '\t\t "0.421601",\n' - '\t\t "0.67528",\n' - '\t\t "0.671502"\n' - "\t\t ]\n" - "\t\t}" - ) + expected_json = ( + "\tmetrics.json:\n" + "\t\t{\n" + '\t\t "data_set": [\n' + '\t\t "train",\n' + '\t\t "testing",\n' + '\t\t "validation"\n' + "\t\t ],\n" + '\t\t "deviation_mse": [\n' + '\t\t "0.173461",\n' + '\t\t "0.289545",\n' + '\t\t "0.297848"\n' + "\t\t ],\n" + '\t\t "value_mse": [\n' + '\t\t "0.421601",\n' + '\t\t "0.67528",\n' + '\t\t "0.671502"\n' + "\t\t ]\n" + "\t\t}" + ) - stdout = logger.logger.handlers[0].stream.getvalue() - self.assertIn(expected_tsv, stdout) - self.assertIn(expected_csv, stdout) - self.assertIn(expected_txt, stdout) - self.assertIn(expected_json, stdout) + stdout = "\n".join(record.message for record in self._caplog.records) + + assert expected_tsv in stdout + assert expected_csv in stdout + assert expected_txt in stdout + assert expected_json in stdout class TestMetricsRecursive(TestDvc): @@ -472,29 +470,29 @@ class TestMetricsCLI(TestMetrics): fd.flush() ret = main(["add", "metric.unknown"]) - self.assertEqual(ret, 0) + assert ret == 0 - with MockLoggerHandlers(logger.logger): - reset_logger_error_output() - ret = main(["metrics", "add", "metric.unknown", "-t", "unknown"]) - self.assertEqual(ret, 1) - self.assertIn( - "failed to add metric file 'metric.unknown' - metric type " - "'unknown' is not supported, must be one of " - "[raw, json, csv, tsv, hcsv, htsv]", - logger.logger.handlers[1].stream.getvalue(), - ) + self._caplog.clear() + ret = main(["metrics", "add", "metric.unknown", "-t", "unknown"]) + assert ret == 1 - ret = main(["metrics", "add", "metric.unknown", "-t", "raw"]) - self.assertEqual(ret, 0) + assert ( + "failed to add metric file 'metric.unknown'" + ) in self._caplog.text - reset_logger_standard_output() - ret = main(["metrics", "show", "metric.unknown"]) - self.assertEqual(ret, 0) - self.assertIn( - "\tmetric.unknown: unknown", - logger.logger.handlers[0].stream.getvalue(), - ) + assert ( + "'unknown' is not supported, must be one of " + "[raw, json, csv, tsv, hcsv, htsv]" + ) in self._caplog.text + + ret = main(["metrics", "add", "metric.unknown", "-t", "raw"]) + assert ret == 0 + + self._caplog.clear() + ret = main(["metrics", "show", "metric.unknown"]) + assert ret == 0 + + assert "\tmetric.unknown: unknown" in self._caplog.text def test_wrong_type_modify(self): with open("metric.unknown", "w+") as fd: @@ -502,31 +500,29 @@ class TestMetricsCLI(TestMetrics): fd.flush() ret = main(["run", "-m", "metric.unknown"]) - self.assertEqual(ret, 0) + assert ret == 0 - with MockLoggerHandlers(logger.logger): - reset_logger_error_output() - ret = main( - ["metrics", "modify", "metric.unknown", "-t", "unknown"] - ) - self.assertEqual(ret, 1) - self.assertIn( - "failed to modify metric file settings - metric type " - "'unknown' is not supported, must be one of " - "[raw, json, csv, tsv, hcsv, htsv]", - logger.logger.handlers[1].stream.getvalue(), - ) + self._caplog.clear() - ret = main(["metrics", "modify", "metric.unknown", "-t", "CSV"]) - self.assertEqual(ret, 0) + ret = main(["metrics", "modify", "metric.unknown", "-t", "unknown"]) + assert ret == 1 - reset_logger_standard_output() - ret = main(["metrics", "show", "metric.unknown"]) - self.assertEqual(ret, 0) - self.assertIn( - "\tmetric.unknown: unknown", - logger.logger.handlers[0].stream.getvalue(), - ) + assert "failed to modify metric file settings" in self._caplog.text + + assert ( + "metric type 'unknown' is not supported, must be one of " + "[raw, json, csv, tsv, hcsv, htsv]" + ) in self._caplog.text + + ret = main(["metrics", "modify", "metric.unknown", "-t", "CSV"]) + assert ret == 0 + + self._caplog.clear() + + ret = main(["metrics", "show", "metric.unknown"]) + assert ret == 0 + + assert "\tmetric.unknown: unknown" in self._caplog.text def test_wrong_type_show(self): with open("metric.unknown", "w+") as fd: @@ -534,26 +530,15 @@ class TestMetricsCLI(TestMetrics): fd.flush() ret = main(["run", "-m", "metric.unknown"]) - self.assertEqual(ret, 0) + assert ret == 0 - with MockLoggerHandlers(logger.logger): - reset_logger_standard_output() - ret = main( - [ - "metrics", - "show", - "metric.unknown", - "-t", - "unknown", - "-x", - "0,0", - ] - ) - self.assertEqual(ret, 0) - self.assertIn( - "\tmetric.unknown: unknown", - logger.logger.handlers[0].stream.getvalue(), - ) + self._caplog.clear() + + ret = main( + ["metrics", "show", "metric.unknown", "-t", "unknown", "-x", "0,0"] + ) + assert ret == 0 + assert "\tmetric.unknown: unknown" in self._caplog.text class TestNoMetrics(TestDvc): diff --git a/tests/test_repro.py b/tests/test_repro.py index 18551c5e3..0cb82aa52 100644 --- a/tests/test_repro.py +++ b/tests/test_repro.py @@ -1,4 +1,3 @@ -from dvc.logger import logger from dvc.utils.compat import str import os @@ -33,10 +32,8 @@ from tests.basic_env import TestDvc from tests.test_data_cloud import _should_test_aws, TEST_AWS_REPO_BUCKET from tests.test_data_cloud import _should_test_gcp, TEST_GCP_REPO_BUCKET from tests.test_data_cloud import _should_test_ssh, _should_test_hdfs -from tests.utils import reset_logger_standard_output from tests.utils.httpd import StaticFileServer from mock import patch -from tests.utils.logger import MockLoggerHandlers class TestRepro(TestDvc): @@ -1394,21 +1391,16 @@ class TestShouldDisplayMetricsOnReproWithMetricsOption(TestDvc): ) self.assertEqual(0, ret) - with MockLoggerHandlers(logger): - reset_logger_standard_output() - ret = main( - [ - "repro", - "--force", - "--metrics", - metrics_file + Stage.STAGE_FILE_SUFFIX, - ] - ) - self.assertEqual(0, ret) + self._caplog.clear() + ret = main( + [ + "repro", + "--force", + "--metrics", + metrics_file + Stage.STAGE_FILE_SUFFIX, + ] + ) + self.assertEqual(0, ret) - expected_metrics_display = "{}: {}".format( - metrics_file, metrics_value - ) - self.assertIn( - expected_metrics_display, logger.handlers[0].stream.getvalue() - ) + expected_metrics_display = "{}: {}".format(metrics_file, metrics_value) + self.assertIn(expected_metrics_display, self._caplog.text) diff --git a/tests/test_tag.py b/tests/test_tag.py index 07244746e..cd3ae6042 100644 --- a/tests/test_tag.py +++ b/tests/test_tag.py @@ -1,15 +1,12 @@ import os import shutil import filecmp +import logging from dvc.main import main -from dvc.logger import logger from tests.basic_env import TestDvc -from tests.utils import reset_logger_standard_output, reset_logger_error_output -from tests.utils.logger import MockLoggerHandlers, ConsoleFontColorsRemover - class TestTag(TestDvc): def test(self): @@ -52,46 +49,45 @@ class TestTagAll(TestDvc): ret = main(["add", self.FOO, self.BAR]) self.assertEqual(ret, 0) - with MockLoggerHandlers(logger), ConsoleFontColorsRemover(): - reset_logger_standard_output() + self._caplog.clear() - ret = main(["tag", "list"]) - self.assertEqual(ret, 0) + ret = main(["tag", "list"]) + self.assertEqual(ret, 0) - self.assertEqual("", logger.handlers[0].stream.getvalue()) + self.assertEqual("", self._caplog.text) ret = main(["tag", "add", "v1"]) self.assertEqual(ret, 0) - with MockLoggerHandlers(logger), ConsoleFontColorsRemover(): - reset_logger_standard_output() + self._caplog.clear() - ret = main(["tag", "list"]) - self.assertEqual(ret, 0) + ret = main(["tag", "list"]) + self.assertEqual(ret, 0) - self.assertEqual( - logger.handlers[0].stream.getvalue(), - "bar.dvc:\n" - " bar:\n" - " v1:\n" - " md5: 8978c98bb5a48c2fb5f2c4c905768afa\n" - "foo.dvc:\n" - " foo:\n" - " v1:\n" - " md5: acbd18db4cc2f85cedef654fccc4a4d8\n" - "\n", - ) + expected = ( + "bar.dvc:\n" + " bar:\n" + " v1:\n" + " md5: 8978c98bb5a48c2fb5f2c4c905768afa\n" + "foo.dvc:\n" + " foo:\n" + " v1:\n" + " md5: acbd18db4cc2f85cedef654fccc4a4d8\n" + ) + + stdout = "\n".join(record.message for record in self._caplog.records) + + assert expected == stdout ret = main(["tag", "remove", "v1"]) self.assertEqual(ret, 0) - with MockLoggerHandlers(logger), ConsoleFontColorsRemover(): - reset_logger_standard_output() + self._caplog.clear() - ret = main(["tag", "list"]) - self.assertEqual(ret, 0) + ret = main(["tag", "list"]) + self.assertEqual(ret, 0) - self.assertEqual("", logger.handlers[0].stream.getvalue()) + self.assertEqual("", self._caplog.text) class TestTagAddNoChecksumInfo(TestDvc): @@ -99,16 +95,13 @@ class TestTagAddNoChecksumInfo(TestDvc): ret = main(["run", "-o", self.FOO, "--no-exec"]) self.assertEqual(ret, 0) - with MockLoggerHandlers(logger), ConsoleFontColorsRemover(): - reset_logger_error_output() + self._caplog.clear() + with self._caplog.at_level(logging.WARNING, logger="dvc"): ret = main(["tag", "add", "v1", "foo.dvc"]) self.assertEqual(ret, 0) - self.assertEqual( - "Warning: missing checksum info for 'foo'\n", - logger.handlers[1].stream.getvalue(), - ) + assert "missing checksum info for 'foo'" in self._caplog.text class TestTagRemoveNoTag(TestDvc): @@ -116,13 +109,10 @@ class TestTagRemoveNoTag(TestDvc): ret = main(["add", self.FOO]) self.assertEqual(ret, 0) - with MockLoggerHandlers(logger), ConsoleFontColorsRemover(): - reset_logger_error_output() + self._caplog.clear() + with self._caplog.at_level(logging.WARNING, logger="dvc"): ret = main(["tag", "remove", "v1", "foo.dvc"]) self.assertEqual(ret, 0) - self.assertEqual( - "Warning: tag 'v1' not found for 'foo'\n", - logger.handlers[1].stream.getvalue(), - ) + assert "tag 'v1' not found for 'foo'" in self._caplog.text diff --git a/tests/test_utils.py b/tests/test_utils.py index 637779c4f..1baf49c22 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -58,3 +58,14 @@ class TestUtils(TestDvc): md5 = "8b263fa05ede6c3145c164829be694b4" self.assertEqual(md5, utils.dict_md5(d, exclude=["metric", "locked"])) + + def test_boxify(self): + expected = ( + "+-----------------+\n" + "| |\n" + "| message |\n" + "| |\n" + "+-----------------+\n" + ) + + assert expected == utils.boxify("message") diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py new file mode 100644 index 000000000..823095a85 --- /dev/null +++ b/tests/unit/test_logger.py @@ -0,0 +1,149 @@ +from __future__ import unicode_literals + +import traceback +import logging +import colorama + +import dvc.logger +from dvc.exceptions import DvcException + + +dvc.logger.setup() +logger = logging.getLogger("dvc") +formatter = dvc.logger.ColorFormatter() +colors = { + "blue": colorama.Fore.BLUE, + "red": colorama.Fore.RED, + "yellow": colorama.Fore.YELLOW, + "nc": colorama.Fore.RESET, +} + + +class TestColorFormatter: + def test_debug(self, caplog): + with caplog.at_level(logging.DEBUG, logger="dvc"): + logger.debug("message") + + expected = "{blue}DEBUG{nc}: message".format(**colors) + + assert expected == formatter.format(caplog.records[0]) + + def test_info(self, caplog): + logger.info("message") + + assert "message" == formatter.format(caplog.records[0]) + + def test_warning(self, caplog): + logger.warning("message") + + expected = "{yellow}WARNING{nc}: message".format(**colors) + + assert expected == formatter.format(caplog.records[0]) + + def test_error(self, caplog): + logger.error("message") + + expected = ( + "{red}ERROR{nc}: message\n" + "\n" + "{footer}".format(footer=formatter.footer, **colors) + ) + + assert expected == formatter.format(caplog.records[0]) + + def test_exception(self, caplog): + try: + raise ValueError + except Exception: + logger.exception("message") + + expected = ( + "{red}ERROR{nc}: message\n" + "\n" + "{footer}".format(footer=formatter.footer, **colors) + ) + + with caplog.at_level(logging.INFO, logger="dvc"): + assert expected == formatter.format(caplog.records[0]) + + def test_exception_with_description_and_without_message(self, caplog): + try: + raise Exception("description") + except Exception: + logger.exception("") + + expected = ( + "{red}ERROR{nc}: description\n" + "\n" + "{footer}".format(footer=formatter.footer, **colors) + ) + + with caplog.at_level(logging.INFO, logger="dvc"): + assert expected == formatter.format(caplog.records[0]) + + def test_exception_with_description_and_message(self, caplog): + with caplog.at_level(logging.INFO, logger="dvc"): + try: + raise Exception("description") + except Exception: + logger.exception("message") + + expected = ( + "{red}ERROR{nc}: message - description\n" + "\n" + "{footer}".format(footer=formatter.footer, **colors) + ) + + assert expected == formatter.format(caplog.records[0]) + + def test_exception_under_verbose(self, caplog): + with caplog.at_level(logging.DEBUG, logger="dvc"): + try: + raise Exception("description") + except Exception: + stack_trace = traceback.format_exc() + logger.exception("") + + expected = ( + "{red}ERROR{nc}: description\n" + "{red}{line}{nc}\n" + "{stack_trace}" + "{red}{line}{nc}\n" + "\n" + "{footer}".format( + footer=formatter.footer, + line="-" * 60, + stack_trace=stack_trace, + **colors + ) + ) + + assert expected == formatter.format(caplog.records[0]) + + def test_nested_exceptions(self, caplog): + with caplog.at_level(logging.DEBUG, logger="dvc"): + try: + raise Exception("first") + except Exception as exc: + first_traceback = traceback.format_exc() + try: + raise DvcException("second", cause=exc) + except DvcException: + second_traceback = traceback.format_exc() + logger.exception("message") + + expected = ( + "{red}ERROR{nc}: message - second: first\n" + "{red}{line}{nc}\n" + "{stack_trace}" + "{red}{line}{nc}\n" + "\n" + "{footer}".format( + footer=formatter.footer, + line="-" * 60, + stack_trace="\n".join([first_traceback, second_traceback]), + **colors + ) + ) + + assert expected == formatter.format(caplog.records[0]) diff --git a/tests/unit/test_progress.py b/tests/unit/test_progress.py index 34de53799..8bcee4167 100644 --- a/tests/unit/test_progress.py +++ b/tests/unit/test_progress.py @@ -1,30 +1,7 @@ import mock from unittest import TestCase -from dvc.progress import progress, progress_aware, ProgressCallback - - -class TestProgressAware(TestCase): - @mock.patch("sys.stdout.isatty", return_value=True) - @mock.patch("dvc.progress.Progress.print") - def test(self, mock_print, _): - # progress is a global object, can be shared between tests when - # run in multi-threading environment with pytest - progress.reset() - function = progress_aware(lambda: None) - - function() - # first - called once for progress.clearln() - mock_print.assert_called_once() - - progress.update_target("testing", 0, 100) - function() - # second - progress.clearln() on refresh on update_target - # third - progress.print on refresh on update_target - # fourth - progress.clearln() - self.assertEqual(4, mock_print.call_count) - - progress.finish_target("testing") +from dvc.progress import ProgressCallback class TestProgressCallback(TestCase): diff --git a/tests/utils/__init__.py b/tests/utils/__init__.py index 7f3d5e282..bb91d0976 100644 --- a/tests/utils/__init__.py +++ b/tests/utils/__init__.py @@ -2,7 +2,6 @@ import yaml import os from dvc.scm import Git -from dvc.utils.compat import StringIO from mock import MagicMock from contextlib import contextmanager @@ -28,18 +27,6 @@ def load_stage_file(path): return yaml.safe_load(fobj) -def reset_logger_error_output(): - from dvc.logger import logger - - logger.handlers[1].stream = StringIO() - - -def reset_logger_standard_output(): - from dvc.logger import logger - - logger.handlers[0].stream = StringIO() - - @contextmanager def cd(newdir): prevdir = os.getcwd() diff --git a/tests/utils/logger.py b/tests/utils/logger.py deleted file mode 100644 index ed127e778..000000000 --- a/tests/utils/logger.py +++ /dev/null @@ -1,35 +0,0 @@ -import logging -from mock import patch -import dvc.logger as logger - - -class MockLoggerHandlers(object): - def __init__(self, l, num=2): - self._logger = l - self._handlers = l.handlers - self._num = num - - def __enter__(self): - self._logger.handlers = [ - logging.FileHandler("tmp{}.log".format(i)) - for i in range(self._num) - ] - return self - - def __exit__(self, exc_type=None, exc_val=None, exc_tb=None): - for h in self._logger.handlers: - h.close() - self._logger.handlers = self._handlers - - -class ConsoleFontColorsRemover(object): - def __init__(self): - self.color_patch = patch.object( - logger, "colorize", new=lambda x, color="": x - ) - - def __enter__(self): - self.color_patch.start() - - def __exit__(self, exc_type=None, exc_val=None, exc_tb=None): - self.color_patch.stop()