From a768fd13ff8ad93444b9f5879963e227b90389b9 Mon Sep 17 00:00:00 2001 From: n3hrox Date: Sat, 26 Oct 2019 22:14:14 +0200 Subject: [PATCH 1/8] logger: output footer once for multithreaded push/pull errors --- dvc/remote/base.py | 8 ++------ dvc/remote/local.py | 17 +++++++++++++++-- 2 files changed, 17 insertions(+), 8 deletions(-) diff --git a/dvc/remote/base.py b/dvc/remote/base.py index f9bd7ef760..30ec6ed6b4 100644 --- a/dvc/remote/base.py +++ b/dvc/remote/base.py @@ -515,9 +515,7 @@ def upload(self, from_info, to_info, name=None, no_progress_bar=False): no_progress_bar=no_progress_bar, ) except Exception: - msg = "failed to upload '{}' to '{}'" - logger.exception(msg.format(from_info, to_info)) - return 1 # 1 fail + return 1, from_info, to_info, "upload" # 1 fail return 0 @@ -555,9 +553,7 @@ def download( from_info, tmp_file, name=name, no_progress_bar=no_progress_bar ) except Exception: - msg = "failed to download '{}' to '{}'" - logger.exception(msg.format(from_info, to_info)) - return 1 # 1 fail + return 1, from_info, to_info, "download" # 1 fail move(tmp_file, to_info, mode=file_mode) diff --git a/dvc/remote/local.py b/dvc/remote/local.py index dff4337566..f9cdb5cdf0 100644 --- a/dvc/remote/local.py +++ b/dvc/remote/local.py @@ -358,11 +358,24 @@ def _process( if len(plans[0]) == 0: return 0 + fails = 0 + msgs = "" if jobs > 1: with TqdmThreadPoolExecutor(max_workers=jobs) as executor: - fails = sum(executor.map(func, *plans)) + failures = executor.map(func, *plans) else: - fails = sum(map(func, *plans)) + failures = list(map(func, *plans)) + + for it in failures: + if not isinstance(it, tuple): + continue + fails += it[0] + from_info, to_info = it[1], it[2] + operation = it[3] + msgs += f"Failed to {operation} '{from_info}' to '{to_info}'\n" + + if msgs: + logger.exception(msgs) if fails: if download: From 2e12af095eb0df7034eacb2e554b98bc5437ee68 Mon Sep 17 00:00:00 2001 From: n3hrox Date: Sat, 26 Oct 2019 22:21:58 +0200 Subject: [PATCH 2/8] Fix improper variable name --- dvc/remote/local.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/dvc/remote/local.py b/dvc/remote/local.py index f9cdb5cdf0..fc11aee287 100644 --- a/dvc/remote/local.py +++ b/dvc/remote/local.py @@ -366,12 +366,12 @@ def _process( else: failures = list(map(func, *plans)) - for it in failures: - if not isinstance(it, tuple): + for failure in failures: + if not isinstance(failure, tuple): continue - fails += it[0] - from_info, to_info = it[1], it[2] - operation = it[3] + fails += failure[0] + from_info, to_info = failure[1], failure[2] + operation = failure[3] msgs += f"Failed to {operation} '{from_info}' to '{to_info}'\n" if msgs: From 98bafa996834b8c7b606db3a806918ef517e7a26 Mon Sep 17 00:00:00 2001 From: n3hrox Date: Sat, 26 Oct 2019 23:01:34 +0200 Subject: [PATCH 3/8] Change f-string to old format --- dvc/remote/local.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/dvc/remote/local.py b/dvc/remote/local.py index fc11aee287..c66a26be37 100644 --- a/dvc/remote/local.py +++ b/dvc/remote/local.py @@ -372,7 +372,9 @@ def _process( fails += failure[0] from_info, to_info = failure[1], failure[2] operation = failure[3] - msgs += f"Failed to {operation} '{from_info}' to '{to_info}'\n" + msgs += "Failed to {} '{}' to '{}'\n".format( + operation, from_info, to_info + ) if msgs: logger.exception(msgs) From 3bf810a832e0241d2c2c0674621eff1b1008a7a2 Mon Sep 17 00:00:00 2001 From: n3hrox Date: Fri, 1 Nov 2019 16:36:31 +0100 Subject: [PATCH 4/8] move footer from logger to main --- dvc/logger.py | 16 +--------------- dvc/main.py | 14 ++++++++++++++ dvc/remote/base.py | 8 ++++++-- dvc/remote/local.py | 19 ++----------------- 4 files changed, 23 insertions(+), 34 deletions(-) diff --git a/dvc/logger.py b/dvc/logger.py index 71f9d9147c..075b1b6800 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -48,16 +48,6 @@ class ColorFormatter(logging.Formatter): "CRITICAL": colorama.Fore.RED, } - 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, - ) - def format(self, record): if record.levelname == "INFO": return record.msg @@ -66,10 +56,7 @@ def format(self, record): exception, stack_trace = self._parse_exc(record.exc_info) return ( - "{color}{levelname}{nc}: {description}" - "{stack_trace}\n" - "\n" - "{footer}" + "{color}{levelname}{nc}: {description}" "{stack_trace}\n" ).format( color=self.color_code.get(record.levelname, ""), nc=colorama.Fore.RESET, @@ -77,7 +64,6 @@ def format(self, record): description=self._description(record.msg, exception), msg=record.msg, stack_trace=stack_trace, - footer=self.footer, ) return "{color}{levelname}{nc}: {msg}".format( diff --git a/dvc/main.py b/dvc/main.py index f8b94b8d31..d21a515927 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -3,6 +3,7 @@ from __future__ import unicode_literals import logging +import colorama from dvc.cli import parse_args from dvc.lock import LockError @@ -16,6 +17,16 @@ logger = logging.getLogger("dvc") +footer = ( + "\n{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, +) + def main(argv=None): """Run dvc CLI command. @@ -75,6 +86,9 @@ def main(argv=None): # so won't be reused by any other subsequent run anyway. clean_repos() + if ret != 0: + logger.info(footer) + Analytics().send_cmd(cmd, args, ret) return ret diff --git a/dvc/remote/base.py b/dvc/remote/base.py index 30ec6ed6b4..cead3293af 100644 --- a/dvc/remote/base.py +++ b/dvc/remote/base.py @@ -515,7 +515,9 @@ def upload(self, from_info, to_info, name=None, no_progress_bar=False): no_progress_bar=no_progress_bar, ) except Exception: - return 1, from_info, to_info, "upload" # 1 fail + msg = "failed to upload '{}' to '{}'" + logger.exception(msg.format(from_info, to_info)) + return 1 # 1 fail return 0 @@ -553,7 +555,9 @@ def download( from_info, tmp_file, name=name, no_progress_bar=no_progress_bar ) except Exception: - return 1, from_info, to_info, "download" # 1 fail + msg = "failed to upload '{}' to '{}'" + logger.exception(msg.format(from_info, to_info)) + return 1 # 1 fail move(tmp_file, to_info, mode=file_mode) diff --git a/dvc/remote/local.py b/dvc/remote/local.py index c66a26be37..dff4337566 100644 --- a/dvc/remote/local.py +++ b/dvc/remote/local.py @@ -358,26 +358,11 @@ def _process( if len(plans[0]) == 0: return 0 - fails = 0 - msgs = "" if jobs > 1: with TqdmThreadPoolExecutor(max_workers=jobs) as executor: - failures = executor.map(func, *plans) + fails = sum(executor.map(func, *plans)) else: - failures = list(map(func, *plans)) - - for failure in failures: - if not isinstance(failure, tuple): - continue - fails += failure[0] - from_info, to_info = failure[1], failure[2] - operation = failure[3] - msgs += "Failed to {} '{}' to '{}'\n".format( - operation, from_info, to_info - ) - - if msgs: - logger.exception(msgs) + fails = sum(map(func, *plans)) if fails: if download: From 8ae1165a9f659b8b258e0e6737b221fa00d3fa24 Mon Sep 17 00:00:00 2001 From: n3hrox Date: Fri, 1 Nov 2019 16:38:23 +0100 Subject: [PATCH 5/8] fix typo upload -> download --- dvc/remote/base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dvc/remote/base.py b/dvc/remote/base.py index cead3293af..f9bd7ef760 100644 --- a/dvc/remote/base.py +++ b/dvc/remote/base.py @@ -555,7 +555,7 @@ def download( from_info, tmp_file, name=name, no_progress_bar=no_progress_bar ) except Exception: - msg = "failed to upload '{}' to '{}'" + msg = "failed to download '{}' to '{}'" logger.exception(msg.format(from_info, to_info)) return 1 # 1 fail From 89502bee88216f2c9cbb99765d8fbc1aa5e31eb0 Mon Sep 17 00:00:00 2001 From: n3hrox Date: Fri, 1 Nov 2019 18:05:27 +0100 Subject: [PATCH 6/8] fix tests --- tests/func/test_remote.py | 2 +- tests/unit/test_logger.py | 38 ++++++++------------------------------ 2 files changed, 9 insertions(+), 31 deletions(-) diff --git a/tests/func/test_remote.py b/tests/func/test_remote.py index b938f97f42..af9d041cf7 100644 --- a/tests/func/test_remote.py +++ b/tests/func/test_remote.py @@ -245,5 +245,5 @@ def unreliable_upload(self, from_file, to_info, name=None, **kwargs): def get_last_exc(caplog): - _, exc, _ = caplog.records[-1].exc_info + _, exc, _ = caplog.records[-2].exc_info return exc diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 5560acd4ea..bcc061ff35 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -45,11 +45,7 @@ def test_error(self, caplog): with caplog.at_level(logging.INFO, logger="dvc"): logger.error("message") - expected = ( - "{red}ERROR{nc}: message\n" - "\n" - "{footer}".format(footer=formatter.footer, **colors) - ) + expected = "{red}ERROR{nc}: message\n".format(**colors) assert expected == formatter.format(caplog.records[0]) @@ -60,11 +56,7 @@ def test_exception(self, caplog): except Exception: logger.exception("message") - expected = ( - "{red}ERROR{nc}: message\n" - "\n" - "{footer}".format(footer=formatter.footer, **colors) - ) + expected = "{red}ERROR{nc}: message\n".format(**colors) assert expected == formatter.format(caplog.records[0]) @@ -75,11 +67,7 @@ def test_exception_with_description_and_without_message(self, caplog): except Exception: logger.exception("") - expected = ( - "{red}ERROR{nc}: description\n" - "\n" - "{footer}".format(footer=formatter.footer, **colors) - ) + expected = "{red}ERROR{nc}: description\n".format(**colors) assert expected == formatter.format(caplog.records[0]) @@ -90,10 +78,8 @@ def test_exception_with_description_and_message(self, caplog): except Exception: logger.exception("message") - expected = ( - "{red}ERROR{nc}: message - description\n" - "\n" - "{footer}".format(footer=formatter.footer, **colors) + expected = "{red}ERROR{nc}: message - description\n".format( + **colors ) assert expected == formatter.format(caplog.records[0]) @@ -110,13 +96,8 @@ def test_exception_under_verbose(self, caplog): "{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 + "{red}{line}{nc}\n".format( + line="-" * 60, stack_trace=stack_trace, **colors ) ) @@ -138,10 +119,7 @@ def test_nested_exceptions(self, caplog): "{red}ERROR{nc}: message - second: first\n" "{red}{line}{nc}\n" "{stack_trace}" - "{red}{line}{nc}\n" - "\n" - "{footer}".format( - footer=formatter.footer, + "{red}{line}{nc}\n".format( line="-" * 60, stack_trace="\n".join([first_traceback, second_traceback]), **colors From 2893c9acad24546f14367e93e35355f59bd6920f Mon Sep 17 00:00:00 2001 From: n3hrox Date: Sun, 3 Nov 2019 22:07:27 +0100 Subject: [PATCH 7/8] move footer to better place and change logging to stderr --- dvc/logger.py | 11 +++++++++++ dvc/main.py | 15 +++------------ 2 files changed, 14 insertions(+), 12 deletions(-) diff --git a/dvc/logger.py b/dvc/logger.py index 075b1b6800..f26ef31cee 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -11,6 +11,17 @@ import colorama +FOOTER = ( + "\n{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, +) + + class LoggingException(Exception): def __init__(self, record): msg = "failed to log {}".format(str(record)) diff --git a/dvc/main.py b/dvc/main.py index d21a515927..287443727b 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -3,10 +3,11 @@ from __future__ import unicode_literals import logging -import colorama +import sys from dvc.cli import parse_args from dvc.lock import LockError +from dvc.logger import FOOTER from dvc.config import ConfigError from dvc.analytics import Analytics from dvc.exceptions import NotDvcRepoError, DvcParserError @@ -17,16 +18,6 @@ logger = logging.getLogger("dvc") -footer = ( - "\n{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, -) - def main(argv=None): """Run dvc CLI command. @@ -87,7 +78,7 @@ def main(argv=None): clean_repos() if ret != 0: - logger.info(footer) + print(FOOTER, file=sys.stderr) Analytics().send_cmd(cmd, args, ret) From d25282ba28c45db92e6b2e9f5416dd2a6fe2530d Mon Sep 17 00:00:00 2001 From: n3hrox Date: Sun, 3 Nov 2019 22:14:59 +0100 Subject: [PATCH 8/8] revert print to logger --- dvc/main.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/dvc/main.py b/dvc/main.py index 287443727b..5d3f01193d 100644 --- a/dvc/main.py +++ b/dvc/main.py @@ -3,7 +3,6 @@ from __future__ import unicode_literals import logging -import sys from dvc.cli import parse_args from dvc.lock import LockError @@ -78,7 +77,7 @@ def main(argv=None): clean_repos() if ret != 0: - print(FOOTER, file=sys.stderr) + logger.info(FOOTER) Analytics().send_cmd(cmd, args, ret)