workingcopy: add tracing about why it might fail

Summary:
When I tried to create a real repo with TESTTMP unset for documentation, I got
mysterious errors like:

  File "/opt/fb/mercurial/edenscm/dirstate.py", line 186, in make_treestate
    ui, opener, root, self._repo._rsrepo.workingcopy().treestate()
    # root = '$TESTTMP/repo1'
  error.WorkingCopyError: working copy is missing information or corrupt: No such file or directory (os error 2) at path "$TESTTMP/repo1/$TESTTMP/.tmp2f2UD9 (ef5a29b32a)"

This diff adds tracing logs in various layers to help narrow it down.

The error message is changed since the underlying errors can be unrelated to
the working copy directly.

For now I just trace the mysterious error down. Note the logs are for component
initialization, which usually just run once. They are not in hot paths to
affect performance.

A more systematic solution might be using the `fn_error_context` crate and
enforce functions returning errors to attach context.

Reviewed By: muirdm

Differential Revision: D42102949

fbshipit-source-id: 6060bebe280a72ab6cd32e4d0eb55e5332612287
This commit is contained in:
Jun Wu 2022-12-16 14:04:17 -08:00 committed by Facebook GitHub Bot
parent 2a1d2efc06
commit 2eb818db71
6 changed files with 66 additions and 12 deletions

View File

@ -22,7 +22,7 @@ pub struct InvalidSharedPath(pub String);
pub struct RemotenamesMetalogKeyError;
#[derive(Debug, Error)]
#[error("working copy is missing information or corrupt: {0}")]
#[error("cannot initialize working copy: {0:?}")]
pub struct InvalidWorkingCopy(#[from] anyhow::Error);
#[derive(Error, Debug)]

View File

@ -12,6 +12,7 @@ use std::path::PathBuf;
use std::sync::Arc;
use anyhow::anyhow;
use anyhow::Context;
use anyhow::Result;
use configloader::config::ConfigSet;
use configloader::Config;
@ -273,7 +274,9 @@ impl Repo {
match &self.eden_api {
Some(eden_api) => Ok(eden_api.clone()),
None => {
tracing::trace!(target: "repo::eden_api", "creating edenapi");
let correlator = edenapi::DEFAULT_CORRELATOR.as_str();
tracing::trace!(target: "repo::eden_api", "getting edenapi builder");
let eden_api = Builder::from_config(&self.config)?
.correlator(Some(correlator))
.build()?;
@ -331,6 +334,7 @@ impl Repo {
return Ok(Arc::new(fs.clone()));
}
tracing::trace!(target: "repo::file_store", "creating edenapi");
let eden_api = if self.store_requirements.contains("git") {
None
} else {
@ -342,6 +346,7 @@ impl Repo {
}
};
tracing::trace!(target: "repo::file_store", "building filestore");
let mut file_builder = FileStoreBuilder::new(self.config())
.local_path(self.store_path())
.correlator(edenapi::DEFAULT_CORRELATOR.as_str());
@ -352,10 +357,12 @@ impl Repo {
file_builder = file_builder.override_edenapi(false);
}
tracing::trace!(target: "repo::file_store", "configuring aux data");
if self.config.get_or_default("scmstore", "auxindexedlog")? {
file_builder = file_builder.store_aux_data();
}
tracing::trace!(target: "repo::file_store", "configuring memcache");
if self
.config
.get_nonempty("remotefilelog", "cachekey")
@ -364,9 +371,12 @@ impl Repo {
file_builder = file_builder.memcache(Arc::new(MemcacheStore::new(&self.config)?));
}
let fs = Arc::new(ArcFileStore(Arc::new(file_builder.build()?)));
tracing::trace!(target: "repo::file_store", "building file store");
let file_store = file_builder.build().context("when building FileStore")?;
let fs = Arc::new(ArcFileStore(Arc::new(file_store)));
self.file_store = Some(fs.clone());
tracing::trace!(target: "repo::file_store", "filestore created");
Ok(fs)
}
@ -443,12 +453,18 @@ impl Repo {
(false, false) => FileSystemType::Normal,
};
tracing::trace!(target: "repo::workingcopy", "initializing vfs at {path:?}");
let vfs = VFS::new(path.to_path_buf())?;
let case_sensitive = vfs.case_sensitive();
tracing::trace!(target: "repo::workingcopy", "case sensitive: {case_sensitive}");
let dirstate_path = path.join(self.ident.dot_dir()).join("dirstate");
tracing::trace!(target: "repo::workingcopy", dirstate_path=?dirstate_path);
let treestate = match filesystem {
FileSystemType::Eden => {
TreeState::from_eden_dirstate(dirstate_path, vfs.case_sensitive())?
tracing::trace!(target: "repo::workingcopy", "loading edenfs dirstate");
TreeState::from_eden_dirstate(dirstate_path, case_sensitive)?
}
_ => {
let treestate_path = path.join(self.ident.dot_dir()).join("treestate");
@ -456,22 +472,24 @@ impl Repo {
.map_err(anyhow::Error::from)?
.is_some()
{
tracing::trace!(target: "repo::workingcopy", "reading dirstate file");
let mut buf =
util::file::open(dirstate_path, "r").map_err(anyhow::Error::from)?;
tracing::trace!(target: "repo::workingcopy", "deserializing dirstate");
let dirstate = Dirstate::deserialize(&mut buf)?;
let fields = dirstate
.tree_state
.ok_or_else(|| anyhow!("missing treestate fields on dirstate"))?;
TreeState::open(
treestate_path.join(fields.tree_filename),
fields.tree_root_id,
vfs.case_sensitive(),
)?
let filename = fields.tree_filename;
let root_id = fields.tree_root_id;
tracing::trace!(target: "repo::workingcopy", "loading treestate {filename} {root_id:?}");
TreeState::open(treestate_path.join(filename), root_id, case_sensitive)?
} else {
let (treestate, root_id) =
TreeState::new(&treestate_path, vfs.case_sensitive())?;
tracing::trace!(target: "repo::workingcopy", "creating treestate");
let (treestate, root_id) = TreeState::new(&treestate_path, case_sensitive)?;
tracing::trace!(target: "repo::workingcopy", "creating dirstate");
let dirstate = Dirstate {
p1: *HgId::null_id(),
p2: *HgId::null_id(),
@ -483,16 +501,23 @@ impl Repo {
}),
};
tracing::trace!(target: "repo::workingcopy", "creating dirstate file");
let mut file =
util::file::create(dirstate_path).map_err(anyhow::Error::from)?;
tracing::trace!(target: "repo::workingcopy", "serializing dirstate");
dirstate.serialize(&mut file)?;
treestate
}
}
};
tracing::trace!(target: "repo::workingcopy", "treestate loaded");
let treestate = Arc::new(Mutex::new(treestate));
tracing::trace!(target: "repo::workingcopy", "creating file store");
let file_store = self.file_store()?;
tracing::trace!(target: "repo::workingcopy", "creating tree resolver");
let tree_resolver = Arc::new(self.tree_resolver()?);
Ok(WorkingCopy::new(

View File

@ -292,41 +292,50 @@ impl<'a> FileStoreBuilder<'a> {
}
pub fn build(mut self) -> Result<FileStore> {
tracing::trace!(target: "revisionstore::filestore", "checking cache");
if self.contentstore.is_none() {
if let Some(cache_path) = cache_path(self.config, &self.suffix)? {
check_cache_buster(&self.config, &cache_path);
}
}
tracing::trace!(target: "revisionstore::filestore", "processing extstored policy");
let extstored_policy = self.get_extstored_policy()?;
tracing::trace!(target: "revisionstore::filestore", "processing lfs threshold");
let lfs_threshold_bytes = self.get_lfs_threshold()?.map(|b| b.value());
let edenapi_retries = self.get_edenapi_retries();
tracing::trace!(target: "revisionstore::filestore", "processing local");
let indexedlog_local = if let Some(indexedlog_local) = self.indexedlog_local.take() {
Some(indexedlog_local)
} else {
self.build_indexedlog_local()?
};
tracing::trace!(target: "revisionstore::filestore", "processing cache");
let indexedlog_cache = if let Some(indexedlog_cache) = self.indexedlog_cache.take() {
Some(indexedlog_cache)
} else {
self.build_indexedlog_cache()?
};
tracing::trace!(target: "revisionstore::filestore", "processing lfs local");
let lfs_local = if let Some(lfs_local) = self.lfs_local.take() {
Some(lfs_local)
} else {
self.build_lfs_local()?
};
tracing::trace!(target: "revisionstore::filestore", "processing lfs cache");
let lfs_cache = if let Some(lfs_cache) = self.lfs_cache.take() {
Some(lfs_cache)
} else {
self.build_lfs_cache()?
};
tracing::trace!(target: "revisionstore::filestore", "processing aux data");
let (aux_local, aux_cache) = if self.store_aux_data {
let aux_local = self.build_aux_local()?;
let aux_cache = self.build_aux_cache()?;
@ -335,6 +344,7 @@ impl<'a> FileStoreBuilder<'a> {
(None, None)
};
tracing::trace!(target: "revisionstore::filestore", "processing lfs remote");
let lfs_remote = if self.use_lfs()? {
if let Some(ref lfs_cache) = lfs_cache {
// TODO(meyer): Refactor upload functionality so we don't need to use LfsRemote with it's own references to the
@ -354,6 +364,7 @@ impl<'a> FileStoreBuilder<'a> {
let memcache = self.memcache.take();
tracing::trace!(target: "revisionstore::filestore", "processing edenapi");
let edenapi = if self.use_edenapi()? {
if let Some(edenapi) = self.edenapi.take() {
Some(edenapi)
@ -364,6 +375,7 @@ impl<'a> FileStoreBuilder<'a> {
None
};
tracing::trace!(target: "revisionstore::filestore", "processing contentstore");
let contentstore = if self
.config
.get_or_default::<bool>("scmstore", "contentstorefallback")?
@ -373,6 +385,7 @@ impl<'a> FileStoreBuilder<'a> {
None
};
tracing::trace!(target: "revisionstore::filestore", "processing fetch logger");
let logging_regex = self
.config
.get_opt::<String>("remotefilelog", "undesiredfileregex")?
@ -399,6 +412,7 @@ impl<'a> FileStoreBuilder<'a> {
None
};
tracing::trace!(target: "revisionstore::filestore", "constructing FileStore");
Ok(FileStore {
extstored_policy,
lfs_threshold_bytes,
@ -592,18 +606,21 @@ impl<'a> TreeStoreBuilder<'a> {
pub fn build(mut self) -> Result<TreeStore> {
// TODO(meyer): Clean this up, just copied and pasted from the other version & did some ugly hacks to get this
// (the EdenApiAdapter stuff needs to be fixed in particular)
tracing::trace!(target: "revisionstore::treestore", "checking cache");
if self.contentstore.is_none() {
if let Some(cache_path) = cache_path(self.config, &self.suffix)? {
check_cache_buster(&self.config, &cache_path);
}
}
tracing::trace!(target: "revisionstore::treestore", "processing local");
let indexedlog_local = if let Some(indexedlog_local) = self.indexedlog_local.take() {
Some(indexedlog_local)
} else {
self.build_indexedlog_local()?
};
tracing::trace!(target: "revisionstore::treestore", "processing cache");
let indexedlog_cache = if let Some(indexedlog_cache) = self.indexedlog_cache.take() {
Some(indexedlog_cache)
} else {
@ -612,6 +629,7 @@ impl<'a> TreeStoreBuilder<'a> {
let memcache = self.memcache.take();
tracing::trace!(target: "revisionstore::treestore", "processing edenapi");
let edenapi = if self.use_edenapi()? {
if let Some(edenapi) = self.edenapi.take() {
Some(edenapi)
@ -622,6 +640,7 @@ impl<'a> TreeStoreBuilder<'a> {
None
};
tracing::trace!(target: "revisionstore::treestore", "processing contentstore");
let contentstore = if self
.config
.get_or_default::<bool>("scmstore", "contentstorefallback")?
@ -631,6 +650,7 @@ impl<'a> TreeStoreBuilder<'a> {
None
};
tracing::trace!(target: "revisionstore::treestore", "constructing TreeStore");
Ok(TreeStore {
indexedlog_local,

View File

@ -63,11 +63,16 @@ impl fmt::Debug for TreeState {
impl TreeState {
/// Read `TreeState` from a file, or create an empty new `TreeState` if `root_id` is None.
pub fn open<P: AsRef<Path>>(path: P, root_id: BlockId, case_sensitive: bool) -> Result<Self> {
let path = path.as_ref();
tracing::trace!(target: "treestate::open", "creating filestore at {path:?}");
let store = FileStore::open(path)?;
let root = {
tracing::trace!(target: "treestate::open", "reading root data");
let mut root_buf = Cursor::new(store.read(root_id)?);
tracing::trace!(target: "treestate::open", "deserializing root data");
TreeStateRoot::deserialize(&mut root_buf)?
};
tracing::trace!(target: "treestate::open", "constructing tree");
let tree = Tree::open(root.tree_block_id(), root.file_count());
Ok(TreeState {
store,
@ -80,9 +85,11 @@ impl TreeState {
}
pub fn new(directory: &Path, case_sensitive: bool) -> Result<(Self, BlockId)> {
tracing::trace!(target: "treestate::create", "creating directory {directory:?}");
create_dir(directory)?;
let name = format!("{:x}", uuid::Uuid::new_v4());
let path = directory.join(&name);
tracing::trace!(target: "treestate::create", "creating filestore {path:?}");
let store = FileStore::create(&path)?;
let root = TreeStateRoot::default();
let tree = Tree::new();
@ -94,8 +101,10 @@ impl TreeState {
eden_dirstate_path: None,
case_sensitive,
};
tracing::trace!(target: "treestate::create", "flushing treestate");
let root_id = treestate.flush()?;
tracing::trace!(target: "treestate::create", "treestate created");
Ok((treestate, root_id))
}

View File

@ -294,7 +294,7 @@ Try other kinds of dirstate corruptions:
... x = f.write(b"x" * 1024)
$ hg log -r . -T '{desc}\n'
warning: failed to inspect working copy parent
abort: working copy is missing information or corrupt: missing treestate fields on dirstate
abort: cannot initialize working copy: missing treestate fields on dirstate
[255]
$ hg doctor

View File

@ -28,5 +28,5 @@ Verify error message when no fallback specified
$ rm .hg/hgrc
$ clearcache
$ hg up tip
abort: working copy is missing information or corrupt: Missing required config item: edenapi.url
abort: cannot initialize working copy: Missing required config item: edenapi.url
[255]