0.2.20240718-145624+f4e9df48: Permission denied (os error 13)

[robhuang]

I recently upgraded to the latest Sapling release 0.2.20240718-145624+f4e9df48. Unfortunately, some commands now result in permission denied errors:

robert@fedora > sl st
abort: Permission denied (os error 13)
robert@fedora > sl rebase -d main
abort: Permission denied (os error 13)
robert@fedora > sl pull # this works
...

I'm on Fedora 40, installed Sapling via Homebrew.

I've hit the same error while running inside a Docker container running Ubuntu 20.04, installed from the prebuilt binary from the releases page.

[sggutier]

@robhuang , can you run some of those commands with --debug --trace? The output from rebase should be specially useful for us.

Also, does $CHGDISABLE=1 sl st help in any way?

[ross-lightsource]

I'm getting a similar failure. Here's the requested output:

$ sl --version
Sapling 0.2.20240718-145624-f4e9df48
(see https://sapling-scm.com/ for more information)

$ sl rebase --debug --trace -d main
watchman sockpath is set as /opt/facebook/watchman/var/run/watchman/ross-state/sock
Traceback (most recent call last):
File "static:sapling.scmutil", line 153, in callcatch
return func()
File "static:sapling.dispatch", line 553, in _runcatchfunc
return _dispatch(req)
File "static:sapling.dispatch", line 1106, in _dispatch
ret = runcommand(
File "static:sapling.ext.undo", line 120, in origunsetpid
return _orig(*args, **opts)
# opts = {}
File "static:sapling.ext.sparse", line 498, in _tracktelemetry
res = runcommand(lui, repo, *args)
File "static:sapling.dispatch", line 789, in runcommand
ret = _runcommand(ui, options, cmd, d)
# cmd = 'rebase'
# options = {'insecure': False, 'verbose': False, 'encodingmode': 'strict', 'repository': '', 'help': False, 'debug': True, 'trace': True, 'noninteractive': False, 'debugger': False, 'pager': 'auto', 'encoding': 'UTF-8', 'hidden': False, 'cwd': '', 'traceback': False, 'profile': False, 'time': False, 'config': [], 'configfile': [], 'quiet': False, 'version': False, 'color': '', 'reason': [], 'outputencoding': 'same as encoding'}
File "static:sapling.dispatch", line 1157, in _runcommand
return cmdfunc()
File "static:sapling.dispatch", line 1105, in
d = lambda: util.checksignature(func)(ui, *args, **strcmdopt)
# strcmdopt = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False}
File "static:sapling.util", line 1376, in check
return func(*args, **kwargs)
# kwargs = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False}
File "static:sapling.util", line 1376, in check
return func(*args, **kwargs)
# kwargs = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False}
File "static:sapling.util", line 1376, in check
return func(*args, **kwargs)
# kwargs = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False}
File "static:sapling.util", line 1376, in check
return func(*args, **kwargs)
# kwargs = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False}
File "static:sapling.util", line 1376, in check
return func(*args, **kwargs)
# kwargs = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False}
File "static:sapling.util", line 1376, in check
return func(*args, **kwargs)
# kwargs = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False}
File "static:sapling.util", line 1376, in check
return func(args, **kwargs)
# kwargs = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False}
File "static:sapling.ext.rebase", line 1289, in rebase
return _origrebase(ui, repo, rbsrt, **opts)
# opts = {'logfile': '', 'restack': False, 'rev': [], 'detach': False, 'noconflict': False, 'template': '', 'interactive': False, 'abort': False, 'tool': '', 'base': '', 'edit': False, 'source': '', 'dest': ['main'], 'quit': False, 'keep': False, 'collapse': False, 'message': '', 'continue': False, 'date': '1724887865 25200'}
File "static:sapling.ext.rebase", line 1378, in _origrebase
destmap = _definedestmap(
File "static:sapling.ext.rebase", line 1603, in _definedestmap
cmdutil.bailifchanged(repo)
File "static:sapling.cmdutil", line 946, in bailifchanged
if uncommittedchanges(repo):
File "static:sapling.cmdutil", line 931, in uncommittedchanges
modified, added, removed, deleted = repo.status()[:4]
File "static:sapling.localrepo", line 3113, in status
return self[node1].status(node2, match, ignored, clean, unknown)
# clean = False
# ignored = False
# node1 = '.'
# unknown = False
File "static:sapling.context", line 389, in status
r = ctx2._buildstatus(ctx1, r, match, listignored, listclean, listunknown)
# ctx1 = <changectx 5733b86d5964>
# ctx2 = <workingctx 5733b86d5964+>
# listclean = False
# listignored = False
# listunknown = False
# r = ([], [], [], [], [], [], [])
# self = <changectx 5733b86d5964>
File "static:sapling.context", line 2046, in _buildstatus
s = self._dirstatestatus(match, listignored, listclean, listunknown)
# listclean = False
# listignored = False
# listunknown = False
# s = ([], [], [], [], [], [], [])
# self = <workingctx 5733b86d5964+>
# self = <workingctx 5733b86d5964+>
File "static:sapling.context", line 1950, in _dirstatestatus
s = self._repo.dirstate.status(
# self = <workingctx 5733b86d5964+>
# self = <workingctx 5733b86d5964+>
File "static:sapling.extensions", line 633, in closure
return func((args + a), **kw)
# kw = {'ignored': False, 'clean': False, 'unknown': False}
File "static:sapling.dirstate", line 852, in status
status = self._repo._rsrepo.workingcopy().status(
PermissionError: [Errno 1] Permission denied (os error 13)
abort: Permission denied (os error 13)

[ross-lightsource]

I spoke to Robert and he downgraded to the previous version 0.2.20240219 to resolve the issue.

[sggutier]

Thanks for the logs @ross-lightsource . Seems like the issue is somewhere in the Rust side of the codebase. Can you run your command as SL_LOG=workingcopy=trace sl rebase --debug --trace -d main to get us even more logs?

[ross-lightsource]

$ SL_LOG=workingcopy=trace sl rebase --debug --trace -d main > rebase.log 2>&1

The result was 17M of details about lightsource source code, so I trimmed out the source code structure details listed in the middle.

rebase.trimmed.log

[PollRobots]

I've also done some digging here with strace

The problem is calls to statx that are failing. This appears to be something walking the tree and looking for .sl folders

In our repo we have a folder .lightsource, which has subdirectories that don't have rx for group or all, i.e. the permissions are dwrx------

The strace log show attempts to stat these directories and to stat for .sl within those directories. These all fail with EACCES (13)

Liberal application of sudo chmod a+rx makes this go away -- this is not a long term solution

the .lightsource directory is in our .gitignore, so I would hope that sapling also ignores it

Adding

[ui]
ignore.internal=.lightsource

to my config does not fix this

[ETA] - this is a trimmed strace log, only including the process that failed, and including the last successful couple of statx calls, then then failures and every log item inbetween. paths are mildly redacted

sl-strace.log

[PollRobots]

FWIW the following patch fixes the issue...

diff --git a/eden/scm/lib/workingcopy/src/filesystem/physicalfs.rs b/eden/scm/lib/workingcopy/src/filesystem/physicalfs.rs
index 3cb5bb8e9c..8526422ee6 100644
--- a/eden/scm/lib/workingcopy/src/filesystem/physicalfs.rs
+++ b/eden/scm/lib/workingcopy/src/filesystem/physicalfs.rs
@@ -43,6 +43,7 @@ use crate::util::dirstate_write_time_override;
 use crate::util::maybe_flush_treestate;
 use crate::util::update_filestate_from_fs_meta;
 use crate::walker::WalkEntry;
+use crate::walker::WalkError;
 use crate::walker::Walker;
 use crate::workingcopy::WorkingCopy;

@@ -304,6 +305,21 @@ impl<M: Matcher + Clone + Send + Sync + 'static> PendingChanges<M> {
                     // Shouldn't happen since we don't request directories.
                 }
                 Some(Err(e)) => {
+                    if e.is::<WalkError>() {
+                        let walk_err = e.downcast::<WalkError>().expect("error should be a walk error");
+                        match &walk_err {
+                            WalkError::IOError(path, _) |
+                            WalkError::InvalidFileType(path) |
+                            WalkError::InvalidMTime(path, _) => {
+                                if self.ignore_matcher.matches_file(&path)? {
+                                    tracing::trace!(%path, %walk_err, "ignore walk error");
+                                    continue;
+                                }
+                            }
+                            _ => {}
+                        }
+                        return Err(walk_err.into())
+                    }
                     return Err(e);
                 }
                 None => {