From 2ffebb0b5ede186d8bc03c3601215f3e74db4866 Mon Sep 17 00:00:00 2001 From: Ruslan Kuprieiev Date: Tue, 17 Mar 2020 00:38:00 +0200 Subject: [PATCH] logger: use standard lazy formatting (#3487) 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 61257ae28..068335ae3 100644 --- a/dvc/external_repo.py +++ b/dvc/external_repo.py @@ -24,7 +24,7 @@ logger = logging.getLogger(__name__) @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 88aec12e0..23f65c061 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 d9cf39ae1..c12f5df91 100644 --- a/dvc/remote/base.py +++ b/dvc/remote/base.py @@ -266,7 +266,7 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): """ 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): ): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 @@ class RemoteBASE(object): 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 9b0ca60ca..3cdfd09fc 100644 --- a/dvc/state.py +++ b/dvc/state.py @@ -137,7 +137,7 @@ class State(object): # pylint: disable=too-many-instance-attributes 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 @@ class State(object): # pylint: disable=too-many-instance-attributes ) 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 @@ class State(object): # pylint: disable=too-many-instance-attributes 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 7e17a8d01..f4b9972d3 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: