From 85cd34415218bb963016d197faad1c70eb97e517 Mon Sep 17 00:00:00 2001 From: "Mr. Outis" Date: Mon, 1 Apr 2019 21:40:14 -0600 Subject: [PATCH 1/2] logger: Use a more _pythonic_ logging - Uses a formatter for coloring output - Move the `progress_aware` decorator logic to the logger itself - Refactor modules so each one uses their own instance of a logger Close #1753 --- dvc/__init__.py | 4 + dvc/analytics.py | 5 +- dvc/cli.py | 4 +- dvc/command/add.py | 7 +- dvc/command/base.py | 16 +- dvc/command/commit.py | 7 +- dvc/command/config.py | 11 +- dvc/command/daemon.py | 1 - dvc/command/data_sync.py | 11 +- dvc/command/destroy.py | 7 +- dvc/command/gc.py | 5 +- dvc/command/imp.py | 7 +- dvc/command/init.py | 7 +- dvc/command/install.py | 7 +- dvc/command/lock.py | 7 +- dvc/command/metrics.py | 13 +- dvc/command/move.py | 7 +- dvc/command/pipeline.py | 10 +- dvc/command/pkg.py | 7 +- dvc/command/remote.py | 6 +- dvc/command/remove.py | 7 +- dvc/command/repro.py | 7 +- dvc/command/root.py | 5 +- dvc/command/run.py | 7 +- dvc/command/status.py | 8 +- dvc/command/tag.py | 11 +- dvc/command/unprotect.py | 7 +- dvc/config.py | 6 +- dvc/daemon.py | 8 +- dvc/data_cloud.py | 7 +- dvc/logger.py | 410 ++++++++++++----------------------- dvc/main.py | 23 +- dvc/output/local.py | 5 +- dvc/progress.py | 16 +- dvc/remote/azure.py | 5 +- dvc/remote/base.py | 5 +- dvc/remote/gs.py | 9 +- dvc/remote/hdfs.py | 5 +- dvc/remote/http.py | 5 +- dvc/remote/local.py | 5 +- dvc/remote/s3.py | 5 +- dvc/remote/ssh/__init__.py | 7 +- dvc/remote/ssh/connection.py | 5 +- dvc/repo/__init__.py | 11 +- dvc/repo/checkout.py | 6 +- dvc/repo/gc.py | 4 +- dvc/repo/init.py | 22 +- dvc/repo/metrics/show.py | 10 +- dvc/repo/pkg.py | 7 +- dvc/repo/reproduce.py | 5 +- dvc/repo/status.py | 5 +- dvc/repo/tag/add.py | 5 +- dvc/repo/tag/remove.py | 5 +- dvc/scm/git/__init__.py | 7 +- dvc/scm/git/temp_git_repo.py | 5 +- dvc/stage.py | 13 +- dvc/state.py | 5 +- dvc/updater.py | 9 +- dvc/utils/__init__.py | 89 +++++++- dvc/utils/fs.py | 5 +- 60 files changed, 520 insertions(+), 420 deletions(-) diff --git a/dvc/__init__.py b/dvc/__init__.py index 8c1eba236f..2a60bc9004 100644 --- a/dvc/__init__.py +++ b/dvc/__init__.py @@ -8,6 +8,10 @@ from dvc.version import __version__ # noqa: F401 import warnings +import dvc.logger + + +dvc.logger.setup() # Ignore numpy's runtime warnings: https://github.com/numpy/numpy/pull/432. # We don't directly import numpy, but our dependency networkx does, causing diff --git a/dvc/analytics.py b/dvc/analytics.py index 0b7a4e94f4..2a7ad7c8fa 100644 --- a/dvc/analytics.py +++ b/dvc/analytics.py @@ -7,11 +7,14 @@ import os import json import errno +import logging -import dvc.logger as logger from dvc import __version__ +logger = logging.getLogger(__name__) + + class Analytics(object): """Class for collecting and sending usage analytics. diff --git a/dvc/cli.py b/dvc/cli.py index d59ec653d8..55949d7154 100644 --- a/dvc/cli.py +++ b/dvc/cli.py @@ -5,8 +5,8 @@ import sys import argparse +import logging -import dvc.logger as logger from dvc.command.base import fix_subparsers import dvc.command.init as init import dvc.command.pkg as pkg @@ -36,6 +36,8 @@ from dvc.exceptions import DvcParserError +logger = logging.getLogger(__name__) + COMMANDS = [ init, pkg, diff --git a/dvc/command/add.py b/dvc/command/add.py index 487dd654db..f6f9ab2799 100644 --- a/dvc/command/add.py +++ b/dvc/command/add.py @@ -1,12 +1,15 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdAdd(CmdBase): def run(self): try: @@ -22,7 +25,7 @@ def run(self): ) except DvcException: - logger.error("failed to add file") + logger.exception("failed to add file") return 1 return 0 diff --git a/dvc/command/base.py b/dvc/command/base.py index 9c9e9eb3cc..c39abb7fac 100644 --- a/dvc/command/base.py +++ b/dvc/command/base.py @@ -1,8 +1,10 @@ from __future__ import unicode_literals import colorama +import logging -import dvc.logger as logger + +logger = logging.getLogger(__name__) def fix_subparsers(subparsers): @@ -40,7 +42,6 @@ def __init__(self, args): self.repo = Repo() self.config = self.repo.config self.args = args - self.set_loglevel(args) @property def default_targets(self): @@ -51,15 +52,6 @@ def default_targets(self): logger.warning(msg) return [Stage.STAGE_FILE] - @staticmethod - def set_loglevel(args): - """Sets log level from CLI arguments.""" - if args.quiet: - logger.be_quiet() - - elif args.verbose: - logger.be_verbose() - def run_cmd(self): from dvc.lock import LockError @@ -67,7 +59,7 @@ def run_cmd(self): with self.repo.lock: return self.run() except LockError: - logger.error("failed to lock before running a command") + logger.exception("failed to lock before running a command") return 1 # Abstract methods that have to be implemented by any inheritance class diff --git a/dvc/command/commit.py b/dvc/command/commit.py index 611f72bf77..fd8f017e9f 100644 --- a/dvc/command/commit.py +++ b/dvc/command/commit.py @@ -1,12 +1,15 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdCommit(CmdBase): def run(self): if not self.args.targets: @@ -21,7 +24,7 @@ def run(self): force=self.args.force, ) except DvcException: - logger.error( + logger.exception( "failed to commit{}".format( (" " + target) if target else "" ) diff --git a/dvc/command/config.py b/dvc/command/config.py index c4c0499823..7cd5948033 100644 --- a/dvc/command/config.py +++ b/dvc/command/config.py @@ -2,13 +2,16 @@ import os import argparse +import logging -import dvc.logger as logger from dvc.command.base import CmdBase, append_doc_link from dvc.config import Config from dvc.exceptions import DvcException +logger = logging.getLogger(__name__) + + class CmdConfig(CmdBase): def __init__(self, args): from dvc.repo import Repo, NotDvcRepoError @@ -47,7 +50,7 @@ def _unset(self, section, opt=None, configobj=None): self.config.unset(configobj, section, opt) self.config.save(configobj) except DvcException: - logger.error("failed to unset '{}'".format(self.args.name)) + logger.exception("failed to unset '{}'".format(self.args.name)) return 1 return 0 @@ -55,7 +58,7 @@ def _show(self, section, opt): try: self.config.show(self.configobj, section, opt) except DvcException: - logger.error("failed to show '{}'".format(self.args.name)) + logger.exception("failed to show '{}'".format(self.args.name)) return 1 return 0 @@ -64,7 +67,7 @@ def _set(self, section, opt, value): self.config.set(self.configobj, section, opt, value) self.config.save(self.configobj) except DvcException: - logger.error( + logger.exception( "failed to set '{}.{}' to '{}'".format(section, opt, value) ) return 1 diff --git a/dvc/command/daemon.py b/dvc/command/daemon.py index db0bf757f6..07b931c72a 100644 --- a/dvc/command/daemon.py +++ b/dvc/command/daemon.py @@ -7,7 +7,6 @@ class CmdDaemonBase(CmdBase): def __init__(self, args): self.args = args self.config = None - self.set_loglevel(args) def run_cmd(self): return self.run() diff --git a/dvc/command/data_sync.py b/dvc/command/data_sync.py index 6937484ffc..f31c2aa87a 100644 --- a/dvc/command/data_sync.py +++ b/dvc/command/data_sync.py @@ -1,11 +1,14 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdDataBase(CmdBase): UP_TO_DATE_MSG = "Everything is up to date." @@ -43,7 +46,7 @@ def do_run(self, target=None): recursive=self.args.recursive, ) except Exception: - logger.error("failed to pull data from the cloud") + logger.exception("failed to pull data from the cloud") return 1 self.check_up_to_date(processed_files_count) return 0 @@ -63,7 +66,7 @@ def do_run(self, target=None): recursive=self.args.recursive, ) except Exception: - logger.error("failed to push data to the cloud") + logger.exception("failed to push data to the cloud") return 1 self.check_up_to_date(processed_files_count) return 0 @@ -83,7 +86,7 @@ def do_run(self, target=None): recursive=self.args.recursive, ) except Exception: - logger.error("failed to fetch data from the cloud") + logger.exception("failed to fetch data from the cloud") return 1 self.check_up_to_date(processed_files_count) return 0 diff --git a/dvc/command/destroy.py b/dvc/command/destroy.py index 837dba18ef..0ffacc1272 100644 --- a/dvc/command/destroy.py +++ b/dvc/command/destroy.py @@ -1,13 +1,16 @@ from __future__ import unicode_literals import argparse +import logging import dvc.prompt as prompt -import dvc.logger as logger from dvc.command.base import CmdBase, append_doc_link from dvc.exceptions import DvcException +logger = logging.getLogger(__name__) + + class CmdDestroy(CmdBase): def run_cmd(self): try: @@ -26,7 +29,7 @@ def run_cmd(self): self.repo.destroy() except Exception: - logger.error("failed to destroy DVC") + logger.exception("failed to destroy DVC") return 1 return 0 diff --git a/dvc/command/gc.py b/dvc/command/gc.py index 582e062900..dc3b191fe3 100644 --- a/dvc/command/gc.py +++ b/dvc/command/gc.py @@ -3,11 +3,14 @@ import argparse import os import dvc.prompt as prompt -import dvc.logger as logger +import logging from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdGC(CmdBase): def run(self): msg = "this will remove all cache except the cache that is used in " diff --git a/dvc/command/imp.py b/dvc/command/imp.py index 6e925ab80a..726bb193c2 100644 --- a/dvc/command/imp.py +++ b/dvc/command/imp.py @@ -2,13 +2,16 @@ import argparse import os +import logging -import dvc.logger as logger from dvc.utils.compat import urlparse from dvc.exceptions import DvcException from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdImport(CmdBase): def run(self): try: @@ -18,7 +21,7 @@ def run(self): self.repo.imp(self.args.url, out, self.args.resume) except DvcException: - logger.error( + logger.exception( "failed to import {}. You could also try downloading " "it manually and adding it with `dvc add` command.".format( self.args.url diff --git a/dvc/command/init.py b/dvc/command/init.py index 3cf1a10ac6..c435a97575 100644 --- a/dvc/command/init.py +++ b/dvc/command/init.py @@ -1,11 +1,14 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.command.base import append_doc_link +logger = logging.getLogger(__name__) + + class CmdInit(object): def __init__(self, args): self.args = args @@ -20,7 +23,7 @@ def run_cmd(self): ) self.config = self.repo.config except InitError: - logger.error("failed to initiate dvc") + logger.exception("failed to initiate dvc") return 1 return 0 diff --git a/dvc/command/install.py b/dvc/command/install.py index 775bfc414f..4967eee6e9 100644 --- a/dvc/command/install.py +++ b/dvc/command/install.py @@ -1,17 +1,20 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdInstall(CmdBase): def run_cmd(self): try: self.repo.install() except Exception: - logger.error("failed to install dvc hooks") + logger.exception("failed to install dvc hooks") return 1 return 0 diff --git a/dvc/command/lock.py b/dvc/command/lock.py index 204bf01088..e435e8dcc5 100644 --- a/dvc/command/lock.py +++ b/dvc/command/lock.py @@ -1,19 +1,22 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdLockBase(CmdBase): def _run(self, unlock): for target in self.args.targets: try: self.repo.lock_stage(target, unlock=unlock) except DvcException: - logger.error( + logger.exception( "failed to {}lock '{}'".format( "un" if unlock else "", target ) diff --git a/dvc/command/metrics.py b/dvc/command/metrics.py index a4ef129c8f..39c53f5b86 100644 --- a/dvc/command/metrics.py +++ b/dvc/command/metrics.py @@ -1,12 +1,15 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, fix_subparsers, append_doc_link +logger = logging.getLogger(__name__) + + def show_metrics(metrics, all_branches=False, all_tags=False): """ Args: @@ -46,7 +49,7 @@ def run(self): show_metrics(metrics, self.args.all_branches, self.args.all_tags) except DvcException: - logger.error("failed to show metrics") + logger.exception("failed to show metrics") return 1 return 0 @@ -59,7 +62,7 @@ def run(self): self.args.path, typ=self.args.type, xpath=self.args.xpath ) except DvcException: - logger.error("failed to modify metric file settings") + logger.exception("failed to modify metric file settings") return 1 return 0 @@ -73,7 +76,7 @@ def run(self): ) except DvcException: msg = "failed to add metric file '{}'".format(self.args.path) - logger.error(msg) + logger.exception(msg) return 1 return 0 @@ -85,7 +88,7 @@ def run(self): self.repo.metrics.remove(self.args.path) except DvcException: msg = "failed to remove metric file '{}'".format(self.args.path) - logger.error(msg) + logger.exception(msg) return 1 return 0 diff --git a/dvc/command/move.py b/dvc/command/move.py index 283344e6aa..4fce351f0c 100644 --- a/dvc/command/move.py +++ b/dvc/command/move.py @@ -1,12 +1,15 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdMove(CmdBase): def run(self): try: @@ -15,7 +18,7 @@ def run(self): msg = "failed to move '{}' -> '{}'".format( self.args.src, self.args.dst ) - logger.error(msg) + logger.exception(msg) return 1 return 0 diff --git a/dvc/command/pipeline.py b/dvc/command/pipeline.py index d1f10341a9..c30160fb9f 100644 --- a/dvc/command/pipeline.py +++ b/dvc/command/pipeline.py @@ -1,16 +1,18 @@ from __future__ import unicode_literals -import argparse - from dvc.utils.compat import str +import argparse import os +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, fix_subparsers, append_doc_link +logger = logging.getLogger(__name__) + + class CmdPipelineShow(CmdBase): def _show(self, target, commands, outs): import networkx @@ -145,7 +147,7 @@ def run(self, unlock=False): self._show(target, self.args.commands, self.args.outs) except DvcException: msg = "failed to show pipeline for '{}'".format(target) - logger.error(msg) + logger.exception(msg) return 1 return 0 diff --git a/dvc/command/pkg.py b/dvc/command/pkg.py index ae313c456f..c1d4ace99a 100644 --- a/dvc/command/pkg.py +++ b/dvc/command/pkg.py @@ -1,13 +1,16 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, fix_subparsers, append_doc_link from dvc.repo.pkg import PackageParams +logger = logging.getLogger(__name__) + + class CmdPkg(CmdBase): def run(self, unlock=False): try: @@ -19,7 +22,7 @@ def run(self, unlock=False): ) return self.repo.install_pkg(pkg_params) except DvcException: - logger.error( + logger.exception( "failed to install package '{}'".format(self.args.address) ) return 1 diff --git a/dvc/command/remote.py b/dvc/command/remote.py index 9bb4876392..1dee14949e 100644 --- a/dvc/command/remote.py +++ b/dvc/command/remote.py @@ -3,13 +3,15 @@ import argparse import os import re +import logging -import dvc.logger as logger -from dvc.command.base import append_doc_link, fix_subparsers from dvc.command.config import CmdConfig from dvc.config import Config +logger = logging.getLogger(__name__) + + class CmdRemoteAdd(CmdConfig): @staticmethod def resolve_path(path, config_file): diff --git a/dvc/command/remove.py b/dvc/command/remove.py index 2d366f8d8b..aa455702bb 100644 --- a/dvc/command/remove.py +++ b/dvc/command/remove.py @@ -1,13 +1,16 @@ from __future__ import unicode_literals import argparse +import logging import dvc.prompt as prompt -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdRemove(CmdBase): def _is_outs_only(self, target): if not self.args.purge: @@ -34,7 +37,7 @@ def run(self): outs_only = self._is_outs_only(target) self.repo.remove(target, outs_only=outs_only) except DvcException: - logger.error("failed to remove {}".format(target)) + logger.exception("failed to remove {}".format(target)) return 1 return 0 diff --git a/dvc/command/repro.py b/dvc/command/repro.py index ba5a17ae0e..3db04b79d9 100644 --- a/dvc/command/repro.py +++ b/dvc/command/repro.py @@ -2,14 +2,17 @@ import argparse import os +import logging -import dvc.logger as logger from dvc.command.base import CmdBase, append_doc_link from dvc.command.metrics import show_metrics from dvc.command.status import CmdDataStatus from dvc.exceptions import DvcException +logger = logging.getLogger(__name__) + + class CmdRepro(CmdBase): def run(self): recursive = not self.args.single_item @@ -45,7 +48,7 @@ def run(self): metrics = self.repo.metrics.show() show_metrics(metrics) except DvcException: - logger.error() + logger.exception() ret = 1 break diff --git a/dvc/command/root.py b/dvc/command/root.py index da154ad97a..f51e19da62 100644 --- a/dvc/command/root.py +++ b/dvc/command/root.py @@ -2,11 +2,14 @@ import argparse import os +import logging -import dvc.logger as logger from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdRoot(CmdBase): def run_cmd(self): return self.run() diff --git a/dvc/command/run.py b/dvc/command/run.py index 619dea51f2..f29e152076 100644 --- a/dvc/command/run.py +++ b/dvc/command/run.py @@ -1,12 +1,15 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.command.base import CmdBase, append_doc_link from dvc.exceptions import DvcException +logger = logging.getLogger(__name__) + + class CmdRun(CmdBase): def run(self): overwrite = self.args.yes or self.args.overwrite_dvcfile @@ -50,7 +53,7 @@ def run(self): outs_persist_no_cache=self.args.outs_persist_no_cache, ) except DvcException: - logger.error("failed to run command") + logger.exception("failed to run command") return 1 return 0 diff --git a/dvc/command/status.py b/dvc/command/status.py index 1e38ed0d82..8a9c945404 100644 --- a/dvc/command/status.py +++ b/dvc/command/status.py @@ -1,10 +1,14 @@ from __future__ import unicode_literals -import dvc.logger as logger +import logging + from dvc.command.data_sync import CmdDataBase from dvc.utils.compat import str +logger = logging.getLogger(__name__) + + class CmdDataStatus(CmdDataBase): STATUS_LEN = 20 STATUS_INDENT = "\t" @@ -58,6 +62,6 @@ def do_run(self, target=None): logger.info(self.UP_TO_DATE_MSG) except Exception: - logger.error("failed to obtain data status") + logger.exception("failed to obtain data status") return 1 return 0 diff --git a/dvc/command/tag.py b/dvc/command/tag.py index ed2367d671..789dacabd4 100644 --- a/dvc/command/tag.py +++ b/dvc/command/tag.py @@ -1,10 +1,13 @@ import yaml +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, fix_subparsers, append_doc_link +logger = logging.getLogger(__name__) + + class CmdTagAdd(CmdBase): def run(self): for target in self.args.targets: @@ -16,7 +19,7 @@ def run(self): recursive=self.args.recursive, ) except DvcException: - logger.error("failed to add tag") + logger.exception("failed to add tag") return 1 return 0 @@ -32,7 +35,7 @@ def run(self): recursive=self.args.recursive, ) except DvcException: - logger.error("failed to remove tag") + logger.exception("failed to remove tag") return 1 return 0 @@ -49,7 +52,7 @@ def run(self): if tags: logger.info(yaml.dump(tags, default_flow_style=False)) except DvcException: - logger.error("failed list tags") + logger.exception("failed list tags") return 1 return 0 diff --git a/dvc/command/unprotect.py b/dvc/command/unprotect.py index 98716952fa..e628489928 100644 --- a/dvc/command/unprotect.py +++ b/dvc/command/unprotect.py @@ -1,12 +1,15 @@ from __future__ import unicode_literals import argparse +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.command.base import CmdBase, append_doc_link +logger = logging.getLogger(__name__) + + class CmdUnprotect(CmdBase): def run(self): for target in self.args.targets: @@ -14,7 +17,7 @@ def run(self): self.repo.unprotect(target) except DvcException: msg = "failed to unprotect '{}'".format(target) - logger.error(msg) + logger.exception(msg) return 1 return 0 diff --git a/dvc/config.py b/dvc/config.py index 8716aacae2..25472546cc 100644 --- a/dvc/config.py +++ b/dvc/config.py @@ -7,11 +7,13 @@ import os import errno import configobj -from schema import Schema, Optional, And, Use, Regex +import logging -import dvc.logger as logger +from schema import Schema, Optional, And, Use, Regex from dvc.exceptions import DvcException +logger = logging.getLogger(__name__) + class ConfigError(DvcException): """DVC config exception. diff --git a/dvc/daemon.py b/dvc/daemon.py index 39731c8442..fc0d1e4584 100644 --- a/dvc/daemon.py +++ b/dvc/daemon.py @@ -5,13 +5,15 @@ import os import sys import inspect +import logging from subprocess import Popen -import dvc.logger as logger from dvc.utils import is_binary, fix_env from dvc.utils.compat import cast_bytes_py2 +logger = logging.getLogger(__name__) + CREATE_NEW_PROCESS_GROUP = 0x00000200 DETACHED_PROCESS = 0x00000008 @@ -43,7 +45,7 @@ def _spawn_posix(cmd, env): if pid > 0: return except OSError: - logger.error("failed at first fork") + logger.exception("failed at first fork") os._exit(1) # pylint: disable=protected-access os.setsid() @@ -54,7 +56,7 @@ def _spawn_posix(cmd, env): if pid > 0: os._exit(0) # pylint: disable=protected-access except OSError: - logger.error("failed at second fork") + logger.exception("failed at second fork") os._exit(1) # pylint: disable=protected-access sys.stdin.close() diff --git a/dvc/data_cloud.py b/dvc/data_cloud.py index e78a0d9160..e5f7f0189c 100644 --- a/dvc/data_cloud.py +++ b/dvc/data_cloud.py @@ -2,9 +2,9 @@ from __future__ import unicode_literals -import dvc.logger as logger -from dvc.config import Config, ConfigError +import logging +from dvc.config import Config, ConfigError from dvc.remote import Remote from dvc.remote.s3 import RemoteS3 from dvc.remote.gs import RemoteGS @@ -15,6 +15,9 @@ from dvc.remote.http import RemoteHTTP +logger = logging.getLogger(__name__) + + class DataCloud(object): """Class that manages dvc remotes. diff --git a/dvc/logger.py b/dvc/logger.py index d756c0d6f9..d6ec9fdd00 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -1,315 +1,173 @@ -"""Manages logger for dvc repo.""" +"""Manages logging configuration for dvc repo.""" from __future__ import unicode_literals -from dvc.exceptions import DvcException from dvc.utils.compat import str -from dvc.progress import progress_aware -import re -import sys import logging -import traceback - -from contextlib import contextmanager - +import logging.handlers +import logging.config import colorama -@progress_aware -def info(message): - """Prints an info message.""" - logger.info(message) - - -# Do not annotate debug with progress_aware. Why? Debug messages are called -# in analytics.py. Trigger introduced by @progress_aware may run even -# if log_level != DEBUG (look at Progress.print) Which might result in -# messy terminal after any command (because analytics run in separate thread) -def debug(message): - """Prints a debug message.""" - prefix = colorize("Debug", color="blue") - - out = "{prefix}: {message}".format(prefix=prefix, message=message) - - logger.debug(out) - - -@progress_aware -def warning(message, parse_exception=False): - """Prints a warning message.""" - prefix = colorize("Warning", color="yellow") - - exception, stack_trace = None, "" - if parse_exception: - exception, stack_trace = _parse_exc() +class ExcludeErrorsFilter(logging.Filter): + def filter(self, record): + return record.levelno < logging.ERROR - out = "{prefix}: {description}".format( - prefix=prefix, description=_description(message, exception) - ) - - if stack_trace: - out += "\n{stack_trace}".format(stack_trace=stack_trace) - - logger.warning(out) - - -@progress_aware -def error(message=None): - """Prints an error message.""" - prefix = colorize("Error", color="red") - - exception, stack_trace = _parse_exc() - - out = ( - "{prefix}: {description}" - "\n" - "{stack_trace}" - "\n" - "{footer}".format( - prefix=prefix, - description=_description(message, exception), - stack_trace=stack_trace, - footer=_footer(), - ) - ) - logger.error(out) +class ColorFormatter(logging.Formatter): + """Enable color support when logging to a terminal that supports it. + Color support on Windows versions that do not support ANSI color codes is + enabled by use of the colorama__ library. + See the colorama documentation for details. -def box(message, border_color=None): - """Prints a message in a box. + __ https://pypi.python.org/pypi/colorama - Args: - message (unicode): message to print. - border_color (unicode): name of a color to outline the box with. + For records containing `exc_info`, it will use a custom `_walk_exc` to + retrieve the whole tracebak. """ - lines = message.split("\n") - max_width = max(_visual_width(line) for line in lines) - - padding_horizontal = 5 - padding_vertical = 1 - - box_size_horizontal = max_width + (padding_horizontal * 2) - chars = {"corner": "+", "horizontal": "-", "vertical": "|", "empty": " "} + color_code = { + "DEBUG": colorama.Fore.BLUE, + "INFO": "", + "WARNING": colorama.Fore.YELLOW, + "ERROR": colorama.Fore.RED, + "CRITICAL": colorama.Fore.RED, + } - margin = "{corner}{line}{corner}\n".format( - corner=chars["corner"], line=chars["horizontal"] * box_size_horizontal + footer = ( + "{yellow}Having any troubles?{nc}." + " Hit us up at {blue}https://dvc.org/support{nc}," + " we are always happy to help!" + ).format( + blue=colorama.Fore.BLUE, + nc=colorama.Fore.RESET, + yellow=colorama.Fore.YELLOW, ) - padding_lines = [ - "{border}{space}{border}\n".format( - border=colorize(chars["vertical"], color=border_color), - space=chars["empty"] * box_size_horizontal, - ) - * padding_vertical - ] - - content_lines = [ - "{border}{space}{content}{space}{border}\n".format( - border=colorize(chars["vertical"], color=border_color), - space=chars["empty"] * padding_horizontal, - content=_visual_center(line, max_width), + 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() + + return ( + "{color}{levelname}{nc}: {description}" + "{stack_trace}\n" + "\n" + "{footer}" + ).format( + color=self.color_code.get(record.levelname, ""), + nc=colorama.Fore.RESET, + levelname=record.levelname, + description=self._description(record.msg, exception), + msg=record.msg, + stack_trace=stack_trace, + footer=self.footer, + ) + + return "{color}{levelname}{nc}: {msg}".format( + color=self.color_code.get(record.levelname, ""), + nc=colorama.Fore.RESET, + levelname=record.levelname, + msg=record.msg, ) - for line in lines - ] - - box_str = "{margin}{padding}{content}{padding}{margin}".format( - margin=colorize(margin, color=border_color), - padding="".join(padding_lines), - content="".join(content_lines), - ) - - logger.info(box_str) - - -def level(): - """Returns current log level.""" - return logger.getEffectiveLevel() - - -def set_level(level_name): - """Sets log level. - - Args: - level_name (str): log level name. E.g. info, debug, warning, error, - critical. - """ - if not level_name: - return - - levels = { - "info": logging.INFO, - "debug": logging.DEBUG, - "warning": logging.WARNING, - "error": logging.ERROR, - "critical": logging.CRITICAL, - } - - logger.setLevel(levels.get(level_name)) - -def be_quiet(): - """Disables all messages except critical ones.""" - logger.setLevel(logging.CRITICAL) + def _description(self, message, exception): + if exception and message: + description = "{message} - {exception}" + elif exception: + description = "{exception}" + elif message: + description = "{message}" + return description.format(message=message, exception=exception) -def be_verbose(): - """Enables all messages.""" - logger.setLevel(logging.DEBUG) + def _walk_exc(self, exc): + import traceback + exc_list = [str(exc)] + tb_list = [traceback.format_exc()] -@contextmanager -def verbose(): - """Enables verbose mode for the context.""" - previous_level = level() - be_verbose() - yield - logger.setLevel(previous_level) + # NOTE: parsing chained exceptions. See dvc/exceptions.py for more info + while hasattr(exc, "cause") and exc.cause is not None: + exc_list.append(str(exc.cause)) + if hasattr(exc, "cause_tb") and exc.cause_tb is not None: + tb_list.insert(0, str(exc.cause_tb)) + exc = exc.cause + return exc_list, tb_list -@contextmanager -def quiet(): - """Enables quiet mode for the context.""" - previous_level = level() - be_quiet() - yield - logger.setLevel(previous_level) + def _parse_exc(self): + import sys + exc = sys.exc_info()[1] + if not exc: + return (None, "") -def is_quiet(): - """Returns whether or not all messages except critical ones are - disabled. - """ - return level() == logging.CRITICAL - + exc_list, tb_list = self._walk_exc(exc) -def is_verbose(): - """Returns whether or not all messages are enabled.""" - return level() == logging.DEBUG + exception = ": ".join(exc_list) + if logging.getLogger("dvc").getEffectiveLevel() == logging.DEBUG: + stack_trace = ( + "\n" "{red}{line}{nc}\n" "{stack_trace}" "{red}{line}{nc}" + ).format( + red=colorama.Fore.RED, + nc=colorama.Fore.RESET, + line="-" * 60, + stack_trace="\n".join(tb_list), + ) + else: + stack_trace = "" -def colorize(message, color=None): - """Returns a message in a specified color.""" - if not color: - return message + return (exception, stack_trace) - colors = { - "green": colorama.Fore.GREEN, - "yellow": colorama.Fore.YELLOW, - "blue": colorama.Fore.BLUE, - "red": colorama.Fore.RED, - } - - return "{color}{message}{nc}".format( - color=colors.get(color, ""), message=message, nc=colorama.Fore.RESET - ) + def _progress_aware(self): + """Add a new line if progress bar hasn't finished""" + from dvc.progress import progress + if not progress.is_finished: + progress._print() + progress.clearln() -def set_default_level(): - """Sets default log level.""" - logger.setLevel(logging.INFO) - -def _add_handlers(): - # NOTE: We need to initialize colorama before setting the stream handlers - # so it can wrap stdout/stderr and convert color codes to Windows. +def setup(level=logging.INFO): colorama.init() - formatter = "%(message)s" - - class _LogLevelFilter(logging.Filter): - # pylint: disable=too-few-public-methods - def filter(self, record): - return record.levelno <= logging.WARNING - - sh_out = logging.StreamHandler(sys.stdout) - sh_out.setFormatter(logging.Formatter(formatter)) - sh_out.setLevel(logging.DEBUG) - sh_out.addFilter(_LogLevelFilter()) - - sh_err = logging.StreamHandler(sys.stderr) - sh_err.setFormatter(logging.Formatter(formatter)) - sh_err.setLevel(logging.ERROR) - - logger.addHandler(sh_out) - logger.addHandler(sh_err) - - -def _walk_exc(exc): - exc_list = [str(exc)] - tb_list = [traceback.format_exc()] - - # NOTE: parsing chained exceptions. See dvc/exceptions.py for more info. - while hasattr(exc, "cause") and exc.cause is not None: - exc_list.append(str(exc.cause)) - if hasattr(exc, "cause_tb") and exc.cause_tb is not None: - tb_list.insert(0, str(exc.cause_tb)) - exc = exc.cause - - return exc_list, tb_list - - -def _parse_exc(): - exc = sys.exc_info()[1] - if not exc: - return (None, "") - - exc_list, tb_list = _walk_exc(exc) - - exception = ": ".join(exc_list) - - if is_verbose(): - stack_trace = "{line}\n{stack_trace}{line}\n".format( - line=colorize("-" * 60, color="red"), - stack_trace="\n".join(tb_list), - ) - else: - stack_trace = "" - - return (exception, stack_trace) - - -def _description(message, exception): - if exception and message: - description = "{message} - {exception}" - elif exception: - description = "{exception}" - elif message: - description = "{message}" - else: - raise DvcException( - "Unexpected error - either exception or message must be provided" - ) - - return description.format(message=message, exception=exception) - - -def _footer(): - return "{phrase} Hit us up at {url}, we are always happy to help!".format( - phrase=colorize("Having any troubles?", "yellow"), - url=colorize("https://dvc.org/support", "blue"), + logging.config.dictConfig( + { + "version": 1, + "filters": {"exclude_errors": {"()": ExcludeErrorsFilter}}, + "formatters": {"color": {"()": ColorFormatter}}, + "handlers": { + "console": { + "class": "logging.StreamHandler", + "level": "DEBUG", + "formatter": "color", + "stream": "ext://sys.stdout", + "filters": ["exclude_errors"], + }, + "console_errors": { + "class": "logging.StreamHandler", + "level": "ERROR", + "formatter": "color", + "stream": "ext://sys.stderr", + }, + }, + "loggers": { + "dvc": { + "level": level, + "handlers": ["console", "console_errors"], + } + }, + } ) - - -def _visual_width(line): - """Get the the number of columns required to display a string""" - - return len(re.sub(colorama.ansitowin32.AnsiToWin32.ANSI_CSI_RE, "", line)) - - -def _visual_center(line, width): - """Center align string according to it's visual width""" - - spaces = max(width - _visual_width(line), 0) - left_padding = int(spaces / 2) - right_padding = spaces - left_padding - - return (left_padding * " ") + line + (right_padding * " ") - - -logger = logging.getLogger("dvc") # pylint: disable=invalid-name - -set_default_level() -_add_handlers() diff --git a/dvc/main.py b/dvc/main.py index 18a9524636..68329f1202 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -2,13 +2,16 @@ from __future__ import unicode_literals -import dvc.logger as logger +import logging + from dvc.cli import parse_args -from dvc.command.base import CmdBase from dvc.analytics import Analytics from dvc.exceptions import NotDvcRepoError, DvcParserError +logger = logging.getLogger("dvc") + + def main(argv=None): """Run dvc CLI command. @@ -20,26 +23,28 @@ def main(argv=None): """ args = None cmd = None + try: args = parse_args(argv) - # Init loglevel early in case we'll run - # into errors before setting it properly - CmdBase.set_loglevel(args) + if args.quiet: + logger.setLevel(logging.CRITICAL) - cmd = args.func(args) + elif args.verbose: + logger.setLevel(logging.DEBUG) + cmd = args.func(args) ret = cmd.run_cmd() except KeyboardInterrupt: - logger.error("interrupted by the user") + logger.exception("interrupted by the user") ret = 252 except NotDvcRepoError: - logger.error() + logger.exception("") ret = 253 except DvcParserError: ret = 254 except Exception: # pylint: disable=broad-except - logger.error("unexpected error") + logger.exception("unexpected error") ret = 255 Analytics().send_cmd(cmd, args, ret) diff --git a/dvc/output/local.py b/dvc/output/local.py index f7cbaca689..b984083b07 100644 --- a/dvc/output/local.py +++ b/dvc/output/local.py @@ -1,8 +1,8 @@ from __future__ import unicode_literals import os +import logging -import dvc.logger as logger from dvc.utils.compat import urlparse from dvc.istextfile import istextfile from dvc.exceptions import DvcException @@ -10,6 +10,9 @@ from dvc.output.base import OutputBase, OutputAlreadyTrackedError +logger = logging.getLogger(__name__) + + class OutputLOCAL(OutputBase): REMOTE = RemoteLOCAL diff --git a/dvc/progress.py b/dvc/progress.py index 8444b808b9..3e247623ee 100644 --- a/dvc/progress.py +++ b/dvc/progress.py @@ -33,11 +33,11 @@ def is_finished(self): return self._n_total == self._n_finished def clearln(self): - self.print(CLEARLINE_PATTERN, end="") + self._print(CLEARLINE_PATTERN, end="") def _writeln(self, line): self.clearln() - self.print(line, end="") + self._print(line, end="") sys.stdout.flush() def reset(self): @@ -74,7 +74,7 @@ def finish_target(self, name): if sys.stdout.isatty(): self.clearln() - self.print(pbar) + self._print(pbar) self._n_finished += 1 self._line = None @@ -106,10 +106,12 @@ def _bar(self, target_name, current, total): return num + pbar + percent + target_name @staticmethod - def print(*args, **kwargs): - import dvc.logger as logger + def _print(*args, **kwargs): + import logging - if logger.is_quiet(): + logger = logging.getLogger(__name__) + + if logger.getEffectiveLevel() == "CRITICAL": return print(*args, **kwargs) @@ -132,7 +134,7 @@ def progress_aware(f): @wraps(f) def wrapper(*args, **kwargs): if not progress.is_finished: - progress.print() + progress._print() progress.clearln() return f(*args, **kwargs) diff --git a/dvc/remote/azure.py b/dvc/remote/azure.py index 99fbcef7b8..da13d942b7 100644 --- a/dvc/remote/azure.py +++ b/dvc/remote/azure.py @@ -3,6 +3,7 @@ import os import re +import logging try: from azure.storage.blob import BlockBlobService @@ -10,7 +11,6 @@ except ImportError: BlockBlobService = None -import dvc.logger as logger from dvc.utils import tmp_fname, move from dvc.utils.compat import urlparse, makedirs from dvc.progress import progress @@ -18,6 +18,9 @@ from dvc.remote.base import RemoteBase +logger = logging.getLogger(__name__) + + class Callback(object): def __init__(self, name): self.name = name diff --git a/dvc/remote/base.py b/dvc/remote/base.py index cdba4c6209..abdcf633c3 100644 --- a/dvc/remote/base.py +++ b/dvc/remote/base.py @@ -4,14 +4,17 @@ import re import posixpath +import logging from multiprocessing import cpu_count import dvc.prompt as prompt -import dvc.logger as logger from dvc.config import Config from dvc.exceptions import DvcException, ConfirmRemoveError +logger = logging.getLogger(__name__) + + STATUS_OK = 1 STATUS_MISSING = 2 STATUS_NEW = 3 diff --git a/dvc/remote/gs.py b/dvc/remote/gs.py index dd57ad9d20..9e494ce976 100644 --- a/dvc/remote/gs.py +++ b/dvc/remote/gs.py @@ -1,13 +1,13 @@ from __future__ import unicode_literals import os +import logging try: from google.cloud import storage except ImportError: storage = None -import dvc.logger as logger from dvc.utils import tmp_fname, move from dvc.utils.compat import urlparse, makedirs from dvc.remote.base import RemoteBase @@ -16,6 +16,9 @@ from dvc.exceptions import DvcException +logger = logging.getLogger(__name__) + + class RemoteGS(RemoteBase): scheme = "gs" REGEX = r"^gs://(?P.*)$" @@ -146,7 +149,7 @@ def upload(self, from_infos, to_infos, names=None): blob.upload_from_filename(from_info["path"]) except Exception: msg = "failed to upload '{}' to '{}/{}'" - logger.error( + logger.exception( msg.format( from_info["path"], to_info["bucket"], to_info["path"] ) @@ -200,7 +203,7 @@ def download( blob.download_to_filename(tmp_file) except Exception: msg = "failed to download '{}/{}' to '{}'" - logger.error( + logger.exception( msg.format( from_info["bucket"], from_info["path"], to_info["path"] ) diff --git a/dvc/remote/hdfs.py b/dvc/remote/hdfs.py index 31620e82e7..4a0a66ff62 100644 --- a/dvc/remote/hdfs.py +++ b/dvc/remote/hdfs.py @@ -4,14 +4,17 @@ import re import getpass import posixpath +import logging from subprocess import Popen, PIPE -import dvc.logger as logger from dvc.config import Config from dvc.remote.base import RemoteBase, RemoteCmdError from dvc.utils import fix_env, tmp_fname +logger = logging.getLogger(__name__) + + class RemoteHDFS(RemoteBase): scheme = "hdfs" REGEX = r"^hdfs://((?P.*)@)?.*$" diff --git a/dvc/remote/http.py b/dvc/remote/http.py index ed587f35b7..2132e1e559 100644 --- a/dvc/remote/http.py +++ b/dvc/remote/http.py @@ -4,8 +4,8 @@ import os import threading import requests +import logging -import dvc.logger as logger from dvc.progress import progress from dvc.exceptions import DvcException from dvc.config import Config @@ -13,6 +13,9 @@ from dvc.utils import move +logger = logging.getLogger(__name__) + + class ProgressBarCallback(object): def __init__(self, name, total): self.name = name diff --git a/dvc/remote/local.py b/dvc/remote/local.py index 702f34ad2c..833f59bb4d 100644 --- a/dvc/remote/local.py +++ b/dvc/remote/local.py @@ -9,9 +9,9 @@ import ntpath import shutil import posixpath +import logging from operator import itemgetter -import dvc.logger as logger from dvc.system import System from dvc.remote.base import ( RemoteBase, @@ -38,6 +38,9 @@ from dvc.utils.fs import get_mtime_and_size, get_inode +logger = logging.getLogger(__name__) + + class RemoteLOCAL(RemoteBase): scheme = "local" REGEX = r"^(?P.*)$" diff --git a/dvc/remote/s3.py b/dvc/remote/s3.py index 8e7f20b7f3..baef66c3e9 100644 --- a/dvc/remote/s3.py +++ b/dvc/remote/s3.py @@ -2,13 +2,13 @@ import os import threading +import logging try: import boto3 except ImportError: boto3 = None -import dvc.logger as logger from dvc.utils import tmp_fname, move from dvc.utils.compat import urlparse, makedirs from dvc.progress import progress @@ -17,6 +17,9 @@ from dvc.exceptions import DvcException +logger = logging.getLogger(__name__) + + class Callback(object): def __init__(self, name, total): self.name = name diff --git a/dvc/remote/ssh/__init__.py b/dvc/remote/ssh/__init__.py index 862247a564..7bcac9557a 100644 --- a/dvc/remote/ssh/__init__.py +++ b/dvc/remote/ssh/__init__.py @@ -1,6 +1,7 @@ from __future__ import unicode_literals import getpass +import logging try: import paramiko @@ -8,13 +9,15 @@ paramiko = None import dvc.prompt as prompt -import dvc.logger as logger from dvc.remote.ssh.connection import SSHConnection from dvc.config import Config from dvc.utils.compat import urlparse from dvc.remote.base import RemoteBase +logger = logging.getLogger(__name__) + + class RemoteSSH(RemoteBase): scheme = "ssh" @@ -184,7 +187,7 @@ def upload(self, from_infos, to_infos, names=None): from_info["path"], to_info["path"], progress_title=name ) except Exception: - logger.error( + logger.exception( "failed to upload '{host}/{path}' to '{dest}'".format( host=from_info["host"], path=from_info["path"], diff --git a/dvc/remote/ssh/connection.py b/dvc/remote/ssh/connection.py index f8576a7f16..3b2b64594f 100644 --- a/dvc/remote/ssh/connection.py +++ b/dvc/remote/ssh/connection.py @@ -1,13 +1,13 @@ import errno import os import posixpath +import logging try: import paramiko except ImportError: paramiko = None -import dvc.logger as logger from dvc.utils import tmp_fname from dvc.utils.compat import makedirs from dvc.progress import progress @@ -15,6 +15,9 @@ from dvc.remote.base import RemoteCmdError +logger = logging.getLogger(__name__) + + def sizeof_fmt(num, suffix="B"): """ Convert number of bytes to human-readable string """ for unit in ["", "K", "M", "G", "T", "P", "E", "Z"]: diff --git a/dvc/repo/__init__.py b/dvc/repo/__init__.py index a082e7c0b1..8a5bc7bc7f 100644 --- a/dvc/repo/__init__.py +++ b/dvc/repo/__init__.py @@ -1,9 +1,9 @@ from __future__ import unicode_literals import os +import logging import dvc.prompt as prompt -import dvc.logger as logger from dvc.exceptions import ( DvcException, @@ -13,6 +13,9 @@ ) +logger = logging.getLogger(__name__) + + class Repo(object): DVC_DIR = ".dvc" @@ -65,7 +68,11 @@ def __init__(self, root_dir=None): core = self.config.config[Config.SECTION_CORE] - logger.set_level(core.get(Config.SECTION_CORE_LOGLEVEL)) + logger.setLevel( + logging.getLevelName( + core.get(Config.SECTION_CORE_LOGLEVEL, "info").upper() + ) + ) self.cache = Cache(self) self.cloud = DataCloud(self, config=self.config.config) diff --git a/dvc/repo/checkout.py b/dvc/repo/checkout.py index d5365a8932..8083feabc4 100644 --- a/dvc/repo/checkout.py +++ b/dvc/repo/checkout.py @@ -1,10 +1,14 @@ from __future__ import unicode_literals -import dvc.logger as logger +import logging + from dvc.exceptions import CheckoutErrorSuggestGit from dvc.progress import ProgressCallback +logger = logging.getLogger(__name__) + + def _cleanup_unused_links(self, all_stages): used = [] for stage in all_stages: diff --git a/dvc/repo/gc.py b/dvc/repo/gc.py index b99c39ac81..58ed42e59a 100644 --- a/dvc/repo/gc.py +++ b/dvc/repo/gc.py @@ -1,8 +1,10 @@ from __future__ import unicode_literals import collections +import logging -import dvc.logger as logger + +logger = logging.getLogger(__name__) def _merge_cache_lists(clists): diff --git a/dvc/repo/init.py b/dvc/repo/init.py index dc23f223ae..ab4fb723a9 100644 --- a/dvc/repo/init.py +++ b/dvc/repo/init.py @@ -1,22 +1,28 @@ import os import shutil import colorama +import logging -import dvc.logger as logger from dvc.repo import Repo from dvc.scm import SCM, NoSCM from dvc.config import Config from dvc.exceptions import InitError +from dvc.utils import boxify + + +logger = logging.getLogger(__name__) def _welcome_message(): - logger.box( - "DVC has enabled anonymous aggregate usage analytics.\n" - "Read the analytics documentation (and how to opt-out) here:\n" - "{blue}https://dvc.org/doc/user-guide/analytics{nc}".format( - blue=colorama.Fore.BLUE, nc=colorama.Fore.RESET - ), - border_color="red", + logger.info( + boxify( + "DVC has enabled anonymous aggregate usage analytics.\n" + "Read the analytics documentation (and how to opt-out) here:\n" + "{blue}https://dvc.org/doc/user-guide/analytics{nc}".format( + blue=colorama.Fore.BLUE, nc=colorama.Fore.RESET + ), + border_color="red", + ) ) msg = ( diff --git a/dvc/repo/metrics/show.py b/dvc/repo/metrics/show.py index 4bbd5a16eb..e331f096b7 100644 --- a/dvc/repo/metrics/show.py +++ b/dvc/repo/metrics/show.py @@ -3,13 +3,16 @@ import os import csv import json +import logging from jsonpath_rw import parse -import dvc.logger as logger from dvc.exceptions import OutputNotFoundError, BadMetricError, NoMetricsError from dvc.utils.compat import builtin_str, open, StringIO, csv_reader +logger = logging.getLogger(__name__) + + def _read_metric_json(fd, json_path): parser = parse(json_path) return [x.value for x in parser.find(json.load(fd))] @@ -136,11 +139,10 @@ def _read_metric(fd, typ=None, xpath=None, rel_path=None, branch=None): # Json path library has to be replaced or wrapped in # order to fix this too broad except clause. except Exception: - logger.warning( + logger.exception( "unable to read metric in '{}' in branch '{}'".format( rel_path, branch - ), - parse_exception=True, + ) ) return None diff --git a/dvc/repo/pkg.py b/dvc/repo/pkg.py index b58d081088..30f57a99dc 100644 --- a/dvc/repo/pkg.py +++ b/dvc/repo/pkg.py @@ -2,13 +2,16 @@ import os import shutil +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.stage import Stage from dvc.scm.git.temp_git_repo import TempGitRepo +logger = logging.getLogger(__name__) + + class PackageParams(object): def __init__(self, address, target_dir, select=[], file=None): self.address = address @@ -196,7 +199,7 @@ def install_pkg(self, pkg_params): mgr = PackageManager.get_package(addr) mgr.install_or_update(self, pkg_params) except Exception as ex: - logger.error("Unable to install package: ".format(ex)) + logger.exception("Unable to install package: ".format(ex)) return 1 return 0 diff --git a/dvc/repo/reproduce.py b/dvc/repo/reproduce.py index 83b1f85e46..54c4d33614 100644 --- a/dvc/repo/reproduce.py +++ b/dvc/repo/reproduce.py @@ -1,12 +1,15 @@ from __future__ import unicode_literals import os +import logging -import dvc.logger as logger from dvc.exceptions import ReproductionError from dvc.repo.scm_context import scm_context +logger = logging.getLogger(__name__) + + def _reproduce_stage(stages, node, force, dry, interactive, no_commit): stage = stages[node] diff --git a/dvc/repo/status.py b/dvc/repo/status.py index da931ed17b..24bc17fc63 100644 --- a/dvc/repo/status.py +++ b/dvc/repo/status.py @@ -1,6 +1,9 @@ from __future__ import unicode_literals -import dvc.logger as logger +import logging + + +logger = logging.getLogger(__name__) def _local_status(self, target=None, with_deps=False): diff --git a/dvc/repo/tag/add.py b/dvc/repo/tag/add.py index 5a06f2129e..4dd866da3c 100644 --- a/dvc/repo/tag/add.py +++ b/dvc/repo/tag/add.py @@ -1,4 +1,7 @@ -import dvc.logger as logger +import logging + + +logger = logging.getLogger(__name__) def add(self, tag, target=None, with_deps=False, recursive=False): diff --git a/dvc/repo/tag/remove.py b/dvc/repo/tag/remove.py index f5f29f8bcf..6ce5401645 100644 --- a/dvc/repo/tag/remove.py +++ b/dvc/repo/tag/remove.py @@ -1,4 +1,7 @@ -import dvc.logger as logger +import logging + + +logger = logging.getLogger(__name__) def remove(self, tag, target=None, with_deps=False, recursive=False): diff --git a/dvc/scm/git/__init__.py b/dvc/scm/git/__init__.py index 9eb49f096d..c6db51da5c 100644 --- a/dvc/scm/git/__init__.py +++ b/dvc/scm/git/__init__.py @@ -3,6 +3,7 @@ from __future__ import unicode_literals import os +import logging from dvc.utils.compat import str, open from dvc.utils import fix_env @@ -13,7 +14,9 @@ FileNotInTargetSubdirError, ) from dvc.scm.git.tree import GitTree -import dvc.logger as logger + + +logger = logging.getLogger(__name__) DIFF_A_TREE = "a_tree" @@ -161,7 +164,7 @@ def add(self, paths): " for more details.".format(str(paths)) ) - logger.error(msg) + logger.exception(msg) def commit(self, msg): self.git.index.commit(msg) diff --git a/dvc/scm/git/temp_git_repo.py b/dvc/scm/git/temp_git_repo.py index 7faf308685..9793a08cf3 100644 --- a/dvc/scm/git/temp_git_repo.py +++ b/dvc/scm/git/temp_git_repo.py @@ -1,11 +1,14 @@ import os import shutil import tempfile +import logging -from dvc import logger from dvc.exceptions import DvcException +logger = logging.getLogger(__name__) + + class TempRepoException(DvcException): """Raise when temporary package repository has not properly created""" diff --git a/dvc/stage.py b/dvc/stage.py index 8aafc029ef..eecfaa2b28 100644 --- a/dvc/stage.py +++ b/dvc/stage.py @@ -6,18 +6,21 @@ import os import yaml import subprocess +import logging from dvc.utils.fs import contains_symlink_up_to from schema import Schema, SchemaError, Optional, Or, And import dvc.prompt as prompt -import dvc.logger as logger import dvc.dependency as dependency import dvc.output as output from dvc.exceptions import DvcException from dvc.utils import dict_md5, fix_env, load_stage_file_fobj +logger = logging.getLogger(__name__) + + class StageCmdFailedError(DvcException): def __init__(self, stage): msg = "stage '{}' cmd {} failed".format(stage.relpath, stage.cmd) @@ -254,13 +257,9 @@ def changed(self): ) if ret: - msg = "Stage '{}' changed.".format(self.relpath) - color = "yellow" + logger.warning("Stage '{}' changed.".format(self.relpath)) else: - msg = "Stage '{}' didn't change.".format(self.relpath) - color = "green" - - logger.info(logger.colorize(msg, color)) + logger.info("Stage '{}' didn't change.".format(self.relpath)) return ret diff --git a/dvc/state.py b/dvc/state.py index d7aee402d7..70c7317fb2 100644 --- a/dvc/state.py +++ b/dvc/state.py @@ -4,14 +4,17 @@ import os import sqlite3 +import logging -import dvc.logger as logger from dvc.config import Config from dvc.utils import file_md5, remove, current_timestamp from dvc.exceptions import DvcException from dvc.utils.fs import get_mtime_and_size, get_inode +logger = logging.getLogger(__name__) + + class StateVersionTooNewError(DvcException): """Thrown when dvc version is older than the state database version.""" diff --git a/dvc/updater.py b/dvc/updater.py index b7bd007604..008e37ea7b 100644 --- a/dvc/updater.py +++ b/dvc/updater.py @@ -3,14 +3,17 @@ import sys import os import time +import logging import requests import colorama from pkg_resources import parse_version from dvc import __version__ -import dvc.logger as logger from dvc.lock import Lock, LockError -from dvc.utils import is_binary +from dvc.utils import is_binary, boxify + + +logger = logging.getLogger(__name__) class Updater(object): # pragma: no cover @@ -110,7 +113,7 @@ def _notify(self): latest=self.latest, ) - logger.box(message, border_color="yellow") + logger.info(boxify(message, border_color="yellow")) def _get_update_instructions(self): instructions = { diff --git a/dvc/utils/__init__.py b/dvc/utils/__init__.py index 624edc7abc..553f503eb1 100644 --- a/dvc/utils/__init__.py +++ b/dvc/utils/__init__.py @@ -14,9 +14,15 @@ import hashlib import nanotime import time +import colorama +import re +import logging from yaml.scanner import ScannerError + +logger = logging.getLogger(__name__) + LOCAL_CHUNK_SIZE = 1024 * 1024 LARGE_FILE_SIZE = 1024 * 1024 * 1024 LARGE_DIR_SIZE = 100 @@ -28,7 +34,6 @@ def dos2unix(data): def file_md5(fname): """ get the (md5 hexdigest, md5 digest) of a file """ - import dvc.logger as logger from dvc.progress import progress from dvc.istextfile import istextfile @@ -152,8 +157,6 @@ def move(src, dst): def remove(path): - import dvc.logger as logger - if not os.path.exists(path): return @@ -249,3 +252,83 @@ def walk_files(directory): for root, _, files in os.walk(str(directory)): for f in files: yield os.path.join(root, f) + + +def colorize(message, color=None): + """Returns a message in a specified color.""" + if not color: + return message + + colors = { + "green": colorama.Fore.GREEN, + "yellow": colorama.Fore.YELLOW, + "blue": colorama.Fore.BLUE, + "red": colorama.Fore.RED, + } + + return "{color}{message}{nc}".format( + color=colors.get(color, ""), message=message, nc=colorama.Fore.RESET + ) + + +def boxify(message, border_color=None): + """Put a message inside a box. + + Args: + message (unicode): message to decorate. + border_color (unicode): name of the color to outline the box with. + """ + lines = message.split("\n") + max_width = max(_visual_width(line) for line in lines) + + padding_horizontal = 5 + padding_vertical = 1 + + box_size_horizontal = max_width + (padding_horizontal * 2) + + chars = {"corner": "+", "horizontal": "-", "vertical": "|", "empty": " "} + + margin = "{corner}{line}{corner}\n".format( + corner=chars["corner"], line=chars["horizontal"] * box_size_horizontal + ) + + padding_lines = [ + "{border}{space}{border}\n".format( + border=colorize(chars["vertical"], color=border_color), + space=chars["empty"] * box_size_horizontal, + ) + * padding_vertical + ] + + content_lines = [ + "{border}{space}{content}{space}{border}\n".format( + border=colorize(chars["vertical"], color=border_color), + space=chars["empty"] * padding_horizontal, + content=_visual_center(line, max_width), + ) + for line in lines + ] + + box_str = "{margin}{padding}{content}{padding}{margin}".format( + margin=colorize(margin, color=border_color), + padding="".join(padding_lines), + content="".join(content_lines), + ) + + return box_str + + +def _visual_width(line): + """Get the the number of columns required to display a string""" + + return len(re.sub(colorama.ansitowin32.AnsiToWin32.ANSI_CSI_RE, "", line)) + + +def _visual_center(line, width): + """Center align string according to it's visual width""" + + spaces = max(width - _visual_width(line), 0) + left_padding = int(spaces / 2) + right_padding = spaces - left_padding + + return (left_padding * " ") + line + (right_padding * " ") diff --git a/dvc/utils/fs.py b/dvc/utils/fs.py index 07efa2d1f7..822ef6401a 100644 --- a/dvc/utils/fs.py +++ b/dvc/utils/fs.py @@ -2,13 +2,16 @@ import nanotime import os +import logging -import dvc.logger as logger from dvc.exceptions import DvcException from dvc.system import System from dvc.utils.compat import str +logger = logging.getLogger(__name__) + + def get_inode(path): inode = System.inode(path) logger.debug("Path {} inode {}".format(path, inode)) From 921b39dbfeb73b28cf6bf2c328ce749e168bd229 Mon Sep 17 00:00:00 2001 From: "Mr. Outis" Date: Tue, 2 Apr 2019 20:56:31 -0600 Subject: [PATCH 2/2] 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 | 74 +++++-------- 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, 419 insertions(+), 583 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 2eb73bd054..ca5245d71c 100644 --- a/dvc/command/diff.py +++ b/dvc/command/diff.py @@ -2,15 +2,17 @@ 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 @@ def run(self): 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 1dee14949e..f69a7ba6ea 100644 --- a/dvc/command/remote.py +++ b/dvc/command/remote.py @@ -5,6 +5,7 @@ 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 d6ec9fdd00..0f428e61dd 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 @@ def format(self, record): ) def _description(self, message, exception): + description = "" + if exception and message: description = "{message} - {exception}" elif exception: @@ -91,29 +87,33 @@ def _description(self, message, exception): 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 3e247623ee..ea0faa2caf 100644 --- a/dvc/progress.py +++ b/dvc/progress.py @@ -127,21 +127,6 @@ def __exit__(self, typ, value, tbck): 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 b44ef40de6..c4cad9fb35 100644 --- a/dvc/prompt.py +++ b/dvc/prompt.py @@ -4,12 +4,15 @@ 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 340c8fb6a4..0198dc7f0f 100644 --- a/tests/basic_env.py +++ b/tests/basic_env.py @@ -6,17 +6,21 @@ 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 @@ def setUp(self): 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 @@ def __init__(self, methodName, root_dir=None): 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 cce7e260ff..1649db7ed9 100644 --- a/tests/test_add.py +++ b/tests/test_add.py @@ -8,7 +8,6 @@ import filecmp import posixpath -from dvc.logger import logger from dvc.system import System from mock import patch @@ -20,8 +19,7 @@ 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 @@ def is_symlink_true_below_dvc_root(path): 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 852223da1f..e263c19388 100644 --- a/tests/test_checkout.py +++ b/tests/test_checkout.py @@ -6,8 +6,8 @@ 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 mock import patch -from tests.utils.logger import MockLoggerHandlers, ConsoleFontColorsRemover + + +logger = logging.getLogger("dvc") class TestCheckout(TestRepro): @@ -404,14 +406,22 @@ def setUp(self): 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 @@ def _prepare_repo(self): 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 e8637defa5..b3f49828e1 100644 --- a/tests/test_data_cloud.py +++ b/tests/test_data_cloud.py @@ -8,12 +8,11 @@ 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.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 @@ def _test(self): 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 @@ def setUp(self): 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() - - ret = main(["push"]) - self.assertEqual(ret, 0) - self.stderr_contains_message() - - 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(["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 + + 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 + + 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 82ebb3d66e..8d770cacd5 100644 --- a/tests/test_import.py +++ b/tests/test_import.py @@ -3,17 +3,16 @@ 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 @@ def test(self): 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 72a3ef21a5..0000000000 --- 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 bfa34366a3..90370264a9 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 @@ def test_formatted_output(self): 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 @@ def test_wrong_type_add(self): 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 @@ def test_wrong_type_modify(self): 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 @@ def test_wrong_type_show(self): 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 18551c5e3f..0cb82aa528 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.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 @@ def test(self): ) 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 07244746ee..cd3ae60427 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 @@ def test(self): 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 @@ def test(self): 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 @@ def test(self): 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 637779c4f2..1baf49c225 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -58,3 +58,14 @@ def test_dict_md5(self): 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 0000000000..823095a859 --- /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 34de537993..8bcee41672 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 7f3d5e282f..bb91d09760 100644 --- a/tests/utils/__init__.py +++ b/tests/utils/__init__.py @@ -2,7 +2,6 @@ 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 ed127e7788..0000000000 --- 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()