From 629e4eea660946571ba82bcf72901e6aefede39e Mon Sep 17 00:00:00 2001 From: Ruslan Kuprieiev Date: Tue, 17 Mar 2020 00:09:51 +0200 Subject: [PATCH] logger: use standard lazy formatting Unfortunately overriding `format` is not enough in order to use our own custom formatting in logger. `Record` uses percent formatting that is hardcoded inside, so we would also have to override it, which is just way too much effort that will inevitably break as we discover other methods that are not ready for non-% formatting. So we are just giving up and sticking to default %-formatting for lazy log messages. Fixes #3397 --- dvc/external_repo.py | 10 +++++----- dvc/logger.py | 3 ++- dvc/remote/base.py | 42 +++++++++++++++++++++--------------------- dvc/state.py | 8 ++++---- dvc/utils/fs.py | 4 ++-- 5 files changed, 34 insertions(+), 33 deletions(-) diff --git a/dvc/external_repo.py b/dvc/external_repo.py index 61257ae28d..068335ae32 100644 --- a/dvc/external_repo.py +++ b/dvc/external_repo.py @@ -24,7 +24,7 @@ @contextmanager def external_repo(url, rev=None, for_write=False): - logger.debug("Creating external repo {}@{}", url, rev) + logger.debug("Creating external repo %s@%s", url, rev) path = _cached_clone(url, rev, for_write=for_write) try: repo = ExternalRepo(path, url) @@ -208,7 +208,7 @@ def _cached_clone(url, rev, for_write=False): # Copy to a new dir to keep the clone clean repo_path = tempfile.mkdtemp("dvc-erepo") - logger.debug("erepo: making a copy of {} clone", url) + logger.debug("erepo: making a copy of %s clone", url) copy_tree(clone_path, repo_path) # Check out the specified revision @@ -234,10 +234,10 @@ def _clone_default_branch(url, rev): git = Git(clone_path) # Do not pull for known shas, branches and tags might move if not Git.is_sha(rev) or not git.has_rev(rev): - logger.debug("erepo: git pull {}", url) + logger.debug("erepo: git pull %s", url) git.pull() else: - logger.debug("erepo: git clone {} to a temporary dir", url) + logger.debug("erepo: git clone %s to a temporary dir", url) clone_path = tempfile.mkdtemp("dvc-clone") git = Git.clone(url, clone_path) CLONES[url] = clone_path @@ -249,7 +249,7 @@ def _clone_default_branch(url, rev): def _git_checkout(repo_path, rev): - logger.debug("erepo: git checkout {}@{}", repo_path, rev) + logger.debug("erepo: git checkout %s@%s", repo_path, rev) git = Git(repo_path) try: git.checkout(rev) diff --git a/dvc/logger.py b/dvc/logger.py index 88aec12e0c..23f65c0616 100644 --- a/dvc/logger.py +++ b/dvc/logger.py @@ -55,7 +55,8 @@ class ColorFormatter(logging.Formatter): } def format(self, record): - msg = record.msg.format(*record.args) if record.args else record.msg + record.message = record.getMessage() + msg = self.formatMessage(record) if record.levelname == "INFO": return msg diff --git a/dvc/remote/base.py b/dvc/remote/base.py index d9cf39ae12..c12f5df91e 100644 --- a/dvc/remote/base.py +++ b/dvc/remote/base.py @@ -266,7 +266,7 @@ def load_dir_cache(self, checksum): if not isinstance(d, list): logger.error( - "dir cache file format error '{}' [skipping the file]", + "dir cache file format error '%s' [skipping the file]", path_info, ) return [] @@ -334,35 +334,35 @@ def changed(self, path_info, checksum_info): """ logger.debug( - "checking if '{}'('{}') has changed.", path_info, checksum_info + "checking if '%s'('%s') has changed.", path_info, checksum_info ) if not self.exists(path_info): - logger.debug("'{}' doesn't exist.", path_info) + logger.debug("'%s' doesn't exist.", path_info) return True checksum = checksum_info.get(self.PARAM_CHECKSUM) if checksum is None: - logger.debug("hash value for '{}' is missing.", path_info) + logger.debug("hash value for '%s' is missing.", path_info) return True if self.changed_cache(checksum): logger.debug( - "cache for '{}'('{}') has changed.", path_info, checksum + "cache for '%s'('%s') has changed.", path_info, checksum ) return True actual = self.get_checksum(path_info) if checksum != actual: logger.debug( - "hash value '{}' for '{}' has changed (actual '{}').", + "hash value '%s' for '%s' has changed (actual '%s').", checksum, actual, path_info, ) return True - logger.debug("'{}' hasn't changed.", path_info) + logger.debug("'%s' hasn't changed.", path_info) return False def link(self, from_info, to_info): @@ -397,7 +397,7 @@ def _try_links(self, from_info, to_info, link_types): except DvcException as exc: logger.debug( - "Cache type '{}' is not supported: {}", link_types[0], exc + "Cache type '%s' is not supported: %s", link_types[0], exc ) del link_types[0] @@ -413,7 +413,7 @@ def _do_link(self, from_info, to_info, link_method): self.protect(to_info) logger.debug( - "Created {}'{}': {} -> {}", + "Created %s'%s': %s -> %s", "protected " if self.protected else "", self.cache_types[0], from_info, @@ -522,7 +522,7 @@ def save(self, path_info, checksum_info): def _save(self, path_info, checksum): to_info = self.checksum_to_path_info(checksum) - logger.debug("Saving '{}' to '{}'.", path_info, to_info) + logger.debug("Saving '%s' to '%s'.", path_info, to_info) if self.isdir(path_info): self._save_dir(path_info, checksum) return @@ -535,7 +535,7 @@ def _handle_transfer_exception( raise exception logger.exception( - "failed to {} '{}' to '{}'", operation, from_info, to_info + "failed to %s '%s' to '%s'", operation, from_info, to_info ) return 1 @@ -549,7 +549,7 @@ def upload(self, from_info, to_info, name=None, no_progress_bar=False): if from_info.scheme != "local": raise NotImplementedError - logger.debug("Uploading '{}' to '{}'", from_info, to_info) + logger.debug("Uploading '%s' to '%s'", from_info, to_info) name = name or from_info.name @@ -628,7 +628,7 @@ def _download_file( ): makedirs(to_info.parent, exist_ok=True, mode=dir_mode) - logger.debug("Downloading '{}' to '{}'", from_info, to_info) + logger.debug("Downloading '%s' to '%s'", from_info, to_info) name = name or to_info.name tmp_file = tmp_fname(to_info) @@ -734,7 +734,7 @@ def changed_cache_file(self, checksum): actual = self.get_checksum(cache_info) logger.debug( - "cache '{}' expected '{}' actual '{}'", + "cache '%s' expected '%s' actual '%s'", cache_info, checksum, actual, @@ -747,7 +747,7 @@ def changed_cache_file(self, checksum): return False if self.exists(cache_info): - logger.warning("corrupted cache file '{}'.", cache_info) + logger.warning("corrupted cache file '%s'.", cache_info) self.remove(cache_info) return True @@ -858,7 +858,7 @@ def _checkout_file( added, modified = True, False cache_info = self.checksum_to_path_info(checksum) if self.exists(path_info): - logger.debug("data '{}' will be replaced.", path_info) + logger.debug("data '%s' will be replaced.", path_info) self.safe_remove(path_info, force=force) added, modified = False, True @@ -893,7 +893,7 @@ def _checkout_dir( dir_info = self.get_dir_cache(checksum) - logger.debug("Linking directory '{}'.", path_info) + logger.debug("Linking directory '%s'.", path_info) for entry in dir_info: relative_path = entry[self.PARAM_RELPATH] @@ -953,21 +953,21 @@ def checkout( skip = False if not checksum: logger.warning( - "No file hash info found for '{}'. " "It won't be created.", + "No file hash info found for '%s'. " "It won't be created.", path_info, ) self.safe_remove(path_info, force=force) failed = path_info elif not relink and not self.changed(path_info, checksum_info): - logger.debug("Data '{}' didn't change.", path_info) + logger.debug("Data '%s' didn't change.", path_info) skip = True elif self.changed_cache( checksum, path_info=path_info, filter_info=filter_info ): logger.warning( - "Cache '{}' not found. File '{}' won't be created.", + "Cache '%s' not found. File '%s' won't be created.", checksum, path_info, ) @@ -986,7 +986,7 @@ def checkout( raise CheckoutError([failed]) return - logger.debug("Checking out '{}' with cache '{}'.", path_info, checksum) + logger.debug("Checking out '%s' with cache '%s'.", path_info, checksum) return self._checkout( path_info, checksum, force, progress_callback, relink, filter_info, diff --git a/dvc/state.py b/dvc/state.py index 9b0ca60ca0..3cdfd09fc2 100644 --- a/dvc/state.py +++ b/dvc/state.py @@ -137,7 +137,7 @@ def _execute(self, cmd, parameters=()): def _fetchall(self): ret = self.cursor.fetchall() - logger.debug("fetched: {}", ret) + logger.debug("fetched: %s", ret) return ret def _to_sqlite(self, num): @@ -178,8 +178,8 @@ def _prepare_db(self, empty=False): ) elif version < self.VERSION: logger.warning( - "State file version '{}' is too old. " - "Reformatting to the current version '{}'.", + "State file version '%d' is too old. " + "Reformatting to the current version '%d'.", version, self.VERSION, ) @@ -460,7 +460,7 @@ def get_unused_links(self, used): actual_mtime, _ = get_mtime_and_size(path, self.repo.tree) if (inode, mtime) == (actual_inode, actual_mtime): - logger.debug("Removing '{}' as unused link.", path) + logger.debug("Removing '%s' as unused link.", path) unused.append(relpath) return unused diff --git a/dvc/utils/fs.py b/dvc/utils/fs.py index 7e17a8d018..f4b9972d31 100644 --- a/dvc/utils/fs.py +++ b/dvc/utils/fs.py @@ -29,7 +29,7 @@ def fs_copy(src, dst): def get_inode(path): inode = System.inode(path) - logger.debug("Path {} inode {}", path, inode) + logger.debug("Path '%s' inode '%d'", path, inode) return inode @@ -130,7 +130,7 @@ def _chmod(func, p, excinfo): def remove(path): - logger.debug("Removing '{}'", path) + logger.debug("Removing '%s'", path) path = fspath_py35(path) try: