Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Access denied error in latest nightly on Windows #3601

Open
daniilS opened this issue Apr 24, 2024 · 23 comments
Open

Access denied error in latest nightly on Windows #3601

daniilS opened this issue Apr 24, 2024 · 23 comments
Assignees
Labels
bug Something isn't working os:windows The Windows platform

Comments

@daniilS
Copy link
Contributor

daniilS commented Apr 24, 2024

Since updating to 0.5.427 (sadly not sure what my previously installed version was exactly, I only know that I installed it at some point last week), I keep getting "Access is denied. (os error 5)" errors on Windows, usually with "Failed to fetch" or "Failed load remote branches". This happens when first opening Gitbutler, or trying to switch or add a new project. Sometimes closing and reopening Gitbutler will load the project and just display the toast, other times it won't load the project at all. When a project does load, actions like creating or deleting a virtual branch sometimes have no effect, and work fine at other times. I've tried running Gitbutler with admin privileges, which didn't solve the problem.

image

image

@daniilS
Copy link
Contributor Author

daniilS commented Apr 24, 2024

Update - can confirm the issue isn't present in stale 0.11.4, if that helps narrow down when it was introduced.

@Byron Byron added bug Something isn't working os:windows The Windows platform labels Apr 24, 2024
@Byron
Copy link
Collaborator

Byron commented Apr 24, 2024

Thanks a lot for reporting!

The very low-level error is probably a result of #3582, which is intended as with help of the logs we should be able to see where it is coming from. If you could find such errors in the logs and post them here, we could identify what's happening and tune the errors to be more descriptive.

The root cause here is probably that reads and writes happen in parallel, which isn't allowed on Windows and GitButler has to get better at coordinating these tasks.

@Byron Byron added the feedback requested Feedback was requested to help resolve the issue label Apr 24, 2024
@Byron Byron self-assigned this Apr 24, 2024
@akbar-mirza
Copy link

I’m encountering a similar issue. It seems to have surfaced in the latest 2-3 nightly builds. Based on the logs, this issue first occurred with app version 0.5.428.

Latest logs (0.5.429) :

Caused by:
    Access is denied. (os error 5)) �[3mproject_id�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e �[3maction�[0m�[2m=�[0mSome("auto")
2024-04-25T03:43:39.513733Z  INFO fetch_from_target: crates\gitbutler-tauri\src\virtual_branches.rs:411: close time.busy=5.10ms time.idle=53.9µs �[3mproject_id�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e �[3maction�[0m�[2m=�[0mSome("auto")
2024-04-25T03:43:39.517170Z  INFO list_projects: crates\gitbutler-tauri\src\projects.rs:51: new
2024-04-25T03:43:39.517442Z  INFO list_projects: crates\gitbutler-tauri\src\projects.rs:51: close time.busy=219µs time.idle=75.7µs
2024-04-25T03:44:33.481377Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:77: new �[3mid�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e �[3mproject_id�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e
2024-04-25T03:44:33.484237Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:77: close time.busy=2.13ms time.idle=748µs �[3mid�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e �[3mproject_id�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e �[3mfs_events�[0m�[2m=�[0m1 �[3mfs_events�[0m�[2m=�[0m1 �[3mignored�[0m�[2m=�[0m0 �[3mignored�[0m�[2m=�[0m0 �[3mgit_noop�[0m�[2m=�[0m1 �[3mgit_noop�[0m�[2m=�[0m1 �[3mgit�[0m�[2m=�[0m0 �[3mgit�[0m�[2m=�[0m0 �[3mproject�[0m�[2m=�[0m0 �[3mproject�[0m�[2m=�[0m0
2024-04-25T03:45:15.765393Z  INFO crates\gitbutler-tauri\src/main.rs:82: starting app version=0.5.429 name=GitButler Nightly
2024-04-25T03:45:16.444132Z  INFO get_user: crates\gitbutler-tauri\src\users.rs:13: new
2024-04-25T03:45:16.444528Z  INFO get_user: crates\gitbutler-tauri\src\users.rs:13: close time.busy=327µs time.idle=112µs
2024-04-25T03:45:16.449106Z  INFO list_projects: crates\gitbutler-tauri\src\projects.rs:51: new
2024-04-25T03:45:16.449355Z  INFO list_projects: crates\gitbutler-tauri\src\projects.rs:51: close time.busy=212µs time.idle=48.6µs
2024-04-25T03:45:16.699283Z  INFO get_project: crates\gitbutler-tauri\src\projects.rs:39: new �[3mid�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e
2024-04-25T03:45:16.703194Z  INFO get_project: crates\gitbutler-tauri\src\projects.rs:39: close time.busy=3.85ms time.idle=85.8µs �[3mid�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e
2024-04-25T03:45:16.704559Z  INFO set_project_active: crates\gitbutler-tauri\src\projects.rs:60: new �[3mid�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e
2024-04-25T03:45:16.704771Z  INFO git_head: crates\gitbutler-tauri\src\commands.rs:97: new �[3mproject_id�[0m�[2m=�[0md19669c3-798e-4b64-bfb3-b6458dca4b2e
2024-04-25T03:45:16.709110Z ERROR git_head: crates\gitbutler-tauri\src\commands.rs:97: error=Error(Access is denied. (os error 5)

@Byron Byron removed the feedback requested Feedback was requested to help resolve the issue label Apr 25, 2024
@Byron
Copy link
Collaborator

Byron commented Apr 25, 2024

Thanks for the logs, everyone!

It seems like the error chain is very short, and that it feels like GitButler is stepping onto its own feet. I will see to land some patches that might improve the situation in the interim, as truly fixing them requires more time.

Byron added a commit to Byron/gitbutler that referenced this issue Apr 25, 2024
…p#3601)

By increasing the window size for collecting filesystem events,
knowing that each event is processed in parallel, we might be lucky
and that already reduces the likelyhood of clashes.

It's an experiment though.
Byron added a commit to Byron/gitbutler that referenced this issue Apr 25, 2024
People can't copy it without the terminal-escape code, making it harder to read.
Byron added a commit to Byron/gitbutler that referenced this issue Apr 25, 2024
…p#3601)

By increasing the window size for collecting filesystem events,
knowing that each event is processed in parallel, we might be lucky
and that already reduces the likelyhood of clashes.

It's an experiment though.

On Unix, run with:

`LOG_LEVEL=debug pnpm tauri dev --features adapt-to-windows`
Byron added a commit to Byron/gitbutler that referenced this issue Apr 25, 2024
People can't copy it without the terminal-escape code, making it harder to read.
@Byron
Copy link
Collaborator

Byron commented Apr 25, 2024

A PR is now available which will make log-excerpts more readable, while trying to reduce the parallelism of the application. This will make it appear more laggy, but might also help reduce the probability of access-denied errors. Fingers crossed.

Byron added a commit to Byron/gitbutler that referenced this issue Apr 25, 2024
This probably means the raciness is not due concurrency introduced by filesystem events,
which leads me to think that having great 'disk-IO-hygiene` should improve things.'
@Byron
Copy link
Collaborator

Byron commented Apr 25, 2024

In conclusion to the failed experiment I can probably say that the issue is indeed caused by disk accesses within serial, unthreaded code. In the experiment, the filesystem monitor was set to only kick in after collecting events for 2 seconds, giving any write operation a long time to finish before reads (and possibly writes, due to lack of IO hygiene) would come in. Since that was ineffective, it must be serial code which is causing this, very reliably so as well.

As an interesting note: button-spamming can make it work after 20-or-so tries.

Byron added a commit that referenced this issue Apr 25, 2024
Revert 74eb7bd as debounce-timing has no effect (#3601)
@Byron
Copy link
Collaborator

Byron commented Apr 26, 2024

I managed to create a local Windows build (see #3505 for the tales of this adventure), and (unfortunately) could add a project without problems.

Screenshot 2024-04-26 at 09 25 19

I tried a few bits of GItButler functionality, but wouldn't run into any access-denied issues.

Could it be that there is some supervisor-process that meddles with files of applications? Admittedly, I disabled all of these as well as I could, and it's impossible to say if my Parallels filesystem truly replicates typical Windows filesystems semantics.

I also couldn't reproduce the issue with GitButler from the release channel.

Hence, it might be worth trying again on a truly real Windows machine. CC @krlvi

@Byron
Copy link
Collaborator

Byron commented Apr 26, 2024

It took me a while to realize that this issue is most likely related to the introduction of tempfile here: 6665bc9 .

There seem to be two writes in short succession, sometimes they succeed, but sometimes one of them fails. Both writes seem to originate in GitButler itself. @daniilS will check if other processes, like Virus Scanners, are interfering, but even if that is the case there was no issue with this previously before tempfiles were introduced.

As an immediate fix, one could selectively disable tempfiles on Windows as it seems to be a problem with consecutive writes, maybe due to some laziness in the filesystem?

@daniilS
Copy link
Contributor Author

daniilS commented Apr 26, 2024

Think I've identified the root cause: tempfile's implementation of persist() on Windows uses MoveFileExW() to move the temporary file to the permanent one (source), which may return before the file is actually written to disk unless the MOVEFILE_WRITE_THROUGH flag is set (source). I suspect this means that if persist() is called in quick succession on different tempfiles, then there's a high chance that multiple writes to projects.json will happen simultaneously, leading to the permission error.

To use tempfiles on Windows, either the implementation of persist() will to set the extra flag, or the file needs to be manually synced before/after each update.

Also worth checking tempfile's implementations of persist() on other OSs to see if any other ones also don't guarantee that the file move is complete when the function returns.

@Byron
Copy link
Collaborator

Byron commented Apr 26, 2024

Thanks so much for this investigation - very helpful, and much appreciated.

It seems like the semantics of perist() differ depending on the platform, as it's atomic on Unix - there isn't anything better than that. On Windows, without write-through, that apparently is not the case, at least not with a truly native filesystem.
A good way to go about this could be to patch persist() locally, create a local Windows build, and provide that to you. If that's working, this means a PR should be created for tempfile, making this behaviour available one way or another.

Looking at the code in Git it becomes clear that it certainly is more advanced on Windows and persist() simply might not be on that level yet.

But this also means, that in the interim, on Windows, tempfiles shouldn't be used anymore until this is fixed upstream.

@daniilS
Copy link
Contributor Author

daniilS commented Apr 26, 2024

Re: the mingw code, it seems to account for some cases where it doesn't have permissions to modify the file. If it does, but still gets an access denied error, it assumes that another process is using the file and just retries after a bit. In our case, I think it's reasonable to assume that gb is the only process using projects.json, and that it should have permissions to access the file, so more complex error handling isn't needed - we just need to make sure gb itself isn't writing to the file twice at the same time.

Agreed that an upstream fix would be ideal - but until then, would it work to call File::sync_all() on projects.json after each write in gix-tempfile?

@Byron
Copy link
Collaborator

Byron commented Apr 27, 2024

Re: the mingw code, it seems to account for some cases where it doesn't have permissions to modify the file. If it does, but still gets an access denied error, it assumes that another process is using the file and just retries after a bit. In our case, I think it's reasonable to assume that gb is the only process using projects.json, and that it should have permissions to access the file, so more complex error handling isn't needed - we just need to make sure gb itself isn't writing to the file twice at the same time.

I absolutely agree with that - GitButler can avoid racing against itself.

Agreed that an upstream fix would be ideal - but until then, would it work to call File::sync_all() on projects.json after each write in gix-tempfile?

sync_all() can be its own bag of flees and I would avoid putting that into gix-tempfile and cause an extra syscall unless I know exactly what's going on. Fortunately, once a tempfile was persisted, one can call sync_all() in GitButler code. And that, we can try first in the next nightly, limiting it to Windows. Otherwise, one can still go back to the previous way of doing things until the upstream fix is available.

Byron added a commit to Byron/gitbutler that referenced this issue Apr 27, 2024
…rapp#3601)

Until `perist()` is truly atomic also on Windows, and modelled
[after Git](https://github.com/git/git/blob/master/compat/mingw.c#L2159-L2209),
sans the retries, it seems to work to just perform ordinary writes.

Before going there though, we try to call `sync_all()` on Windows to truly
finish the operation. On Unix, a rename is already supposed to be atomic.
Byron added a commit to Byron/gitbutler that referenced this issue Apr 27, 2024
…rapp#3601)

Until `perist()` is truly atomic also on Windows, and modelled
[after Git](https://github.com/git/git/blob/master/compat/mingw.c#L2159-L2209),
sans the retries, it seems to work to just perform ordinary writes.

Before going there though, we try to call `sync_all()` on Windows to truly
finish the operation. On Unix, a rename is already supposed to be atomic.
Byron added a commit to Byron/gitbutler that referenced this issue Apr 27, 2024
…rapp#3601)

Until `perist()` is truly atomic also on Windows, and modelled
[after Git](https://github.com/git/git/blob/master/compat/mingw.c#L2159-L2209),
sans the retries, it seems to work to just perform ordinary writes.

Before going there though, we try to call `sync_all()` on Windows to truly
finish the operation. On Unix, a rename is already supposed to be atomic.
Byron added a commit to Byron/gitbutler that referenced this issue Apr 27, 2024
…rapp#3601)

Until `perist()` is truly atomic also on Windows, and modelled
[after Git](https://github.com/git/git/blob/master/compat/mingw.c#L2159-L2209),
sans the retries, it seems to work to just perform ordinary writes.

Before going there though, we try to call `sync_all()` on Windows to truly
finish the operation. On Unix, a rename is already supposed to be atomic.
Byron added a commit to Byron/gitbutler that referenced this issue Apr 27, 2024
…rapp#3601)

Until `perist()` is truly atomic also on Windows, and modelled
[after Git](https://github.com/git/git/blob/master/compat/mingw.c#L2159-L2209),
sans the retries, it seems to work to just perform ordinary writes.

Before going there though, we try to call `sync_all()` on Windows to truly
finish the operation. On Unix, a rename is already supposed to be atomic.
@Qix-
Copy link
Contributor

Qix- commented Apr 30, 2024

@Byron since #3620, is this fixed? If so, should we close this or do you want to keep it open to track an upstream change?

@Qix- Qix- added the feedback requested Feedback was requested to help resolve the issue label Apr 30, 2024
@krlvi
Copy link
Member

krlvi commented May 2, 2024

@Qix- we have this mitigated by not using temp files on windows for now (which exposes us to other problems).
I found this very similar issue on cargo rust-lang/cargo#11544 and I am still not sure how to do filesystem operations properly on windows.

@Byron
Copy link
Collaborator

Byron commented May 13, 2024

Just as a summary, this issue was raised when atomic-writes were first introduced, in order to prevent half-written files to corrupt the GB repository.

Thus, getting this to work on Windows properly is still desirable. There is one more thing to try in the tempfile crate which will hopefully improve the overall stability, even though I am not sure it will help much with fast consecutive writes which could still clash in the destination.

For the latter case, rename failures, it seems that Git retries up to 5 times on Windows with pre-defined delays, which is something that could be implemented in gix-tempfile.

Of course, fast consecutive writes, even if they go through with trickery, might not necessarily go through in the right order anymore, potentially causing a different set of issues. This PR aims to help with making this less likely.

@Byron
Copy link
Collaborator

Byron commented May 16, 2024

After talking to @anaisbetts I also learned that there is a FILE_SHARE_DELETE flag which should allow the deletion of files that are currently opened. So if mv a.lock a just replaced a, and Windows Defender opens a, the next mv a.lock a would fail as a is opened. But if FILE_SHARE_DELETE is set on a, it can be overwritten while still being available to the reader.

With that, the MOVEFILE_WRITE_THROUGH might not be needed as we wouldn't care anymore if a is truly already there, after all, now we should always be able to overwrite it.

Byron added a commit to Byron/gitbutler that referenced this issue May 25, 2024
The sync-all didn't do anything, and one would still run into locked
files.
Byron added a commit to Byron/gitbutler that referenced this issue May 25, 2024
The sync-all didn't do anything, and one would still run into locked
files.
@Byron
Copy link
Collaborator

Byron commented May 25, 2024

Finally I was able to create the test-build which contains some tempfile modifications which might just make this work.

It will run on x86-64 Windows systems.

gitbutler-tauri-2024-05-25-01.exe.zip

How this binary is different?

The build uses a locally modified tempfile crate, with these modifications. In theory, this should allow the Windows filesystem to be more lenient and allow tempfiles to be overwritten while opened, and if that's not enough, it should also wait until the rename operation is complete, ideally without just failing.

Resources

Next steps

The idea is that if this does indeed work, I will produce another binary without the MOVEFILE_WRITE_THROUGH flag set to be sure it isn't actually required, or more generally to find the minimal fix. Then I will try to get this change accepted in the upstream crate.

More Notes

When opening source-code in the RustRover IDE on Windows, it popped up a message saying that Windows Defender was enabled and the project path should be excluded from it to avoid severe performance degradation. It then offers to run an admin-script to make these exclusions for you.

It would probably be too much for GitButler to offer doing so as well, but it might be something to try out doing by hand - do the access-denied problems go away once Defender doesn't interfere?

@anaisbetts
Copy link
Contributor

It would probably be too much for GitButler to offer doing so as well, but it might be something to try out doing by hand - do the access-denied problems go away once Defender doesn't interfere?

While this is probably good for users to do for performance reasons, it is also something that GitButler shouldn't do - we want to solve locking bugs, not hide them!

@Byron
Copy link
Collaborator

Byron commented May 26, 2024

we want to solve locking bugs, not hide them!

I meant it as a test to see if Defender is a common reason for these errors, and not to say that should be the (only) way GitButler can work correctly on Windows.
So I really hope this executable is working.

@slingshotvfx
Copy link

slingshotvfx commented Jun 7, 2024

Just for reference, I still receive a lot of access denied errors on windows 11 with the latest gitbutler v0.12.2

Here's a recent one:

image

image

and the log:

2024-06-07T20:18:10.876268Z  INFO handle:calculate_virtual_branches:workdir: crates\gitbutler-core\src\git\diff.rs:146: new event=VirtualBranch(573feb84-1a51-4d52-a85c-89faf4ee7fd1) commit_oid=b15b54f190c5946b385b3921093a3289f1bcd639
2024-06-07T20:18:11.181138Z  INFO handle:calculate_virtual_branches:workdir: crates\gitbutler-core\src\git\diff.rs:146: close time.busy=305ms time.idle=27.6µs event=VirtualBranch(573feb84-1a51-4d52-a85c-89faf4ee7fd1) commit_oid=b15b54f190c5946b385b3921093a3289f1bcd639
2024-06-07T20:18:11.206577Z  INFO handle:calculate_virtual_branches: crates\gitbutler-watcher\src\handler.rs:85: close time.busy=368ms time.idle=400ms event=VirtualBranch(573feb84-1a51-4d52-a85c-89faf4ee7fd1)
2024-06-07T20:18:11.206598Z ERROR handle: crates\gitbutler-watcher\src\handler.rs:54: error=failed to handle virtual branch event

Caused by:
    0: failed to list virtual branches
    1: failed to write virtual branch csv-import-error-handling-fixes
    2: Access is denied. (os error 5) event=VirtualBranch(573feb84-1a51-4d52-a85c-89faf4ee7fd1)
2024-06-07T20:18:11.206603Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: close time.busy=368ms time.idle=400ms event=VirtualBranch(573feb84-1a51-4d52-a85c-89faf4ee7fd1)
2024-06-07T20:18:11.236620Z  INFO list_virtual_branches:workdir: crates\gitbutler-core\src\git\diff.rs:146: new project_id=573feb84-1a51-4d52-a85c-89faf4ee7fd1 commit_oid=57c5648a65152c85f1b467c4fc1b9acfefc806a8
2024-06-07T20:18:11.563077Z  INFO list_virtual_branches:workdir: crates\gitbutler-core\src\git\diff.rs:146: close time.busy=326ms time.idle=24.3µs project_id=573feb84-1a51-4d52-a85c-89faf4ee7fd1 commit_oid=57c5648a65152c85f1b467c4fc1b9acfefc806a8
2024-06-07T20:18:11.581593Z ERROR list_virtual_branches: crates\gitbutler-tauri\src\virtual_branches.rs:39: error=Error(failed to write virtual branch csv-import-error-handling-fixes

Caused by:
    Access is denied. (os error 5)) project_id=573feb84-1a51-4d52-a85c-89faf4ee7fd1
2024-06-07T20:18:11.581604Z  INFO list_virtual_branches: crates\gitbutler-tauri\src\virtual_branches.rs:39: close time.busy=375ms time.idle=767ms project_id=573feb84-1a51-4d52-a85c-89faf4ee7fd1
2024-06-07T20:18:12.174534Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: new id=573feb84-1a51-4d52-a85c-89faf4ee7fd1 project_id=573feb84-1a51-4d52-a85c-89faf4ee7fd1
2024-06-07T20:18:12.174891Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: close time.busy=336µs time.idle=23.2µs id=573feb84-1a51-4d52-a85c-89faf4ee7fd1 project_id=573feb84-1a51-4d52-a85c-89faf4ee7fd1 fs_events=379 fs_events=379 ignored=0 ignored=0 git_noop=378 git_noop=378 git=1 git=1 project=0 project=0 git_dedup=1 git_dedup=1

@Byron
Copy link
Collaborator

Byron commented Jun 8, 2024

Thanks everyone for your help with testing this, and for bearing with us.

I have compiled another executable based on 0.12.2 (c6b22a7 specifically) which should in theory have less trouble with access-denied errors. It's an updated version of the executable from the earlier comment and if it proves to be better/more stable/more usable than the current stable or nightly I think we can go into further testing and finally, try to upstream the change I made to the Windows version of the tempfile crate.

Finally, after all that pre-amble, here is the new executable.

@slingshotvfx
Copy link

Hey @Byron,

Thanks for looking into this. I played around with that exe a bit. Unfortunately I'm not sure performance improved much (or at all?), and I still hit access denied errors.

initial open

First, I was simply trying to switch back to the gitbutler/integration branch and got

image

2024-06-10T18:59:01.832581Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: new id=3aa9ba5d-9859-4236-a625-edc3e341b303 project_id=3aa9ba5d-9859-4236-a625-edc3e341b303
2024-06-10T18:59:01.835046Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: close time.busy=2.44ms time.idle=32.9µs id=3aa9ba5d-9859-4236-a625-edc3e341b303 project_id=3aa9ba5d-9859-4236-a625-edc3e341b303 fs_events=8 fs_events=8 ignored=0 ignored=0 git_noop=2 git_noop=2 git=1 git=1 project=2 project=2 git_dedup=1 git_dedup=1 project_dedup=2 project_dedup=2
2024-06-10T18:59:01.835288Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: new event=GitFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, index)
2024-06-10T18:59:01.835350Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: new event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>\<redacted>.py, <redacted>)
2024-06-10T18:59:01.835361Z  INFO handle:recalculate_everything: crates\gitbutler-watcher\src\handler.rs:114: new event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>\<redacted>.py, <redacted>) paths=2
2024-06-10T18:59:01.835396Z  INFO handle:recalculate_everything:calculate_virtual_branches: crates\gitbutler-watcher\src\handler.rs:85: new event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>\<redacted>.py, <redacted>) paths=2
2024-06-10T18:59:01.835451Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: close time.busy=152µs time.idle=11.3µs event=GitFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, index)
2024-06-10T18:59:01.837257Z  INFO handle:recalculate_everything:calculate_virtual_branches: crates\gitbutler-watcher\src\handler.rs:85: close time.busy=1.85ms time.idle=10.4µs event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>\<redacted>.py, <redacted>) paths=2
2024-06-10T18:59:01.837266Z  INFO handle:recalculate_everything: crates\gitbutler-watcher\src\handler.rs:114: close time.busy=1.90ms time.idle=7.40µs event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>\<redacted>.py, <redacted>) paths=2
2024-06-10T18:59:01.837270Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: close time.busy=1.91ms time.idle=11.9µs event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>\<redacted>.py, <redacted>)
2024-06-10T18:59:09.493050Z  INFO set_base_branch: crates\gitbutler-tauri\src\virtual_branches.rs:121: new project_id=3aa9ba5d-9859-4236-a625-edc3e341b303 branch="origin/main" push_remote=None
2024-06-10T18:59:09.496900Z  INFO set_base_branch:create_snapshot: crates\gitbutler-core\src\ops\oplog.rs:250: new project_id=3aa9ba5d-9859-4236-a625-edc3e341b303 branch="origin/main" push_remote=None self=Project { id: 3aa9ba5d-9859-4236-a625-edc3e341b303, title: "main", description: None, path: "C:\\Users\\<redacted>\\Documents\\main", preferred_key: SystemExecutable, ok_with_force_push: true, api: None, gitbutler_data_last_fetch: None, gitbutler_code_push_state: None, project_data_last_fetch: Some(Error { timestamp: SystemTime { intervals: 133625191393713015 }, error: "backend error: failed to execute git command: The system cannot find the file specified. (os error 2)" }), omit_certificate_check: None, snapshot_lines_threshold: None, use_new_locking: false }
2024-06-10T18:59:09.544688Z  INFO set_base_branch:create_snapshot: crates\gitbutler-core\src\ops\oplog.rs:250: close time.busy=47.8ms time.idle=24.7µs project_id=3aa9ba5d-9859-4236-a625-edc3e341b303 branch="origin/main" push_remote=None self=Project { id: 3aa9ba5d-9859-4236-a625-edc3e341b303, title: "main", description: None, path: "C:\\Users\\<redacted>\\Documents\\main", preferred_key: SystemExecutable, ok_with_force_push: true, api: None, gitbutler_data_last_fetch: None, gitbutler_code_push_state: None, project_data_last_fetch: Some(Error { timestamp: SystemTime { intervals: 133625191393713015 }, error: "backend error: failed to execute git command: The system cannot find the file specified. (os error 2)" }), omit_certificate_check: None, snapshot_lines_threshold: None, use_new_locking: false }
2024-06-10T18:59:09.571516Z ERROR set_base_branch: crates\gitbutler-tauri\src\virtual_branches.rs:121: error=Error(failed to checkout tree

Caused by:
    failed rmdir - 'C:/Users/<redacted>/Documents/<redacted>/' is locked: Access is denied.
    ; class=Os (2); code=Locked (-14)) project_id=3aa9ba5d-9859-4236-a625-edc3e341b303 branch="origin/main" push_remote=None
2024-06-10T18:59:09.571530Z  INFO set_base_branch: crates\gitbutler-tauri\src\virtual_branches.rs:121: close time.busy=78.5ms time.idle=27.3µs project_id=3aa9ba5d-9859-4236-a625-edc3e341b303 branch="origin/main" push_remote=None
2024-06-10T18:59:09.673334Z  INFO get_base_branch_data: crates\gitbutler-tauri\src\virtual_branches.rs:103: new project_id=3aa9ba5d-9859-4236-a625-edc3e341b303
2024-06-10T18:59:09.678709Z  INFO get_base_branch_data: crates\gitbutler-tauri\src\virtual_branches.rs:103: close time.busy=5.35ms time.idle=24.2µs project_id=3aa9ba5d-9859-4236-a625-edc3e341b303
2024-06-10T18:59:10.341635Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: new id=3aa9ba5d-9859-4236-a625-edc3e341b303 project_id=3aa9ba5d-9859-4236-a625-edc3e341b303
2024-06-10T18:59:10.347150Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: close time.busy=5.48ms time.idle=38.6µs id=3aa9ba5d-9859-4236-a625-edc3e341b303 project_id=3aa9ba5d-9859-4236-a625-edc3e341b303 fs_events=90 fs_events=90 ignored=0 ignored=0 git_noop=82 git_noop=82 git=0 git=0 project=2 project=2 project_dedup=2 project_dedup=2
2024-06-10T18:59:10.347221Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: new event=GitButlerOplogChange(3aa9ba5d-9859-4236-a625-edc3e341b303)
2024-06-10T18:59:10.347240Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: new event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>, <redacted>\<redacted>.py)
2024-06-10T18:59:10.347250Z  INFO handle:recalculate_everything: crates\gitbutler-watcher\src\handler.rs:114: new event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>, <redacted>.py) paths=2
2024-06-10T18:59:10.347273Z  INFO handle:recalculate_everything:calculate_virtual_branches: crates\gitbutler-watcher\src\handler.rs:85: new event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>, <redacted>.py) paths=2
2024-06-10T18:59:10.348128Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: close time.busy=864µs time.idle=44.6µs event=GitButlerOplogChange(3aa9ba5d-9859-4236-a625-edc3e341b303)
2024-06-10T18:59:10.352311Z  INFO handle:recalculate_everything:calculate_virtual_branches: crates\gitbutler-watcher\src\handler.rs:85: close time.busy=5.02ms time.idle=13.6µs event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>, <redacted>\<redacted>.py) paths=2
2024-06-10T18:59:10.352332Z  INFO handle:recalculate_everything: crates\gitbutler-watcher\src\handler.rs:114: close time.busy=5.07ms time.idle=14.8µs event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>, <redacted>\<redacted>.py) paths=2
2024-06-10T18:59:10.352341Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: close time.busy=5.09ms time.idle=16.6µs event=ProjectFileChange(3aa9ba5d-9859-4236-a625-edc3e341b303, <redacted>, <redacted>\<redacted>.py)

I can DM someone the logs without redacted paths, but every instance of was the exact same path, and the .py file was actually deleted.

updating workspace

I moved on from that by completely deleting and re-adding the project. I was able to commit a few changes and apply a few different virtual branches successfully. Unfortunately, after merging a PR/deleting a branch in github and then clicking the red "Update" workspace button in gitbutler, I encountered another access denied error:

image

2024-06-10T19:44:37.007770Z  INFO update_base_branch: crates\gitbutler-tauri\src\virtual_branches.rs:152: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:44:37.015271Z  INFO update_base_branch:create_snapshot: crates\gitbutler-core\src\ops\oplog.rs:250: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e self=Project { id: 46469d3a-393a-450c-8f07-f5520ddf033e, title: "main", description: None, path: "C:\\Users\\<redacted>\\Documents\\main", preferred_key: SystemExecutable, ok_with_force_push: true, api: None, gitbutler_data_last_fetch: None, gitbutler_code_push_state: None, project_data_last_fetch: Some(Fetched { timestamp: SystemTime { intervals: 133625222667112155 } }), omit_certificate_check: None, snapshot_lines_threshold: None, use_new_locking: true }
2024-06-10T19:44:37.091707Z  INFO update_base_branch:create_snapshot: crates\gitbutler-core\src\ops\oplog.rs:250: close time.busy=76.4ms time.idle=21.0µs project_id=46469d3a-393a-450c-8f07-f5520ddf033e self=Project { id: 46469d3a-393a-450c-8f07-f5520ddf033e, title: "main", description: None, path: "C:\\Users\\<redacted>\\Documents\\main", preferred_key: SystemExecutable, ok_with_force_push: true, api: None, gitbutler_data_last_fetch: None, gitbutler_code_push_state: None, project_data_last_fetch: Some(Fetched { timestamp: SystemTime { intervals: 133625222667112155 } }), omit_certificate_check: None, snapshot_lines_threshold: None, use_new_locking: true }
2024-06-10T19:44:37.099319Z  INFO update_base_branch:workdir: crates\gitbutler-core\src\git\diff.rs:146: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e commit_oid=5efcc944de627de5baab84b11517011d2c82992c
2024-06-10T19:44:37.422071Z  INFO update_base_branch:workdir: crates\gitbutler-core\src\git\diff.rs:146: close time.busy=323ms time.idle=23.1µs project_id=46469d3a-393a-450c-8f07-f5520ddf033e commit_oid=5efcc944de627de5baab84b11517011d2c82992c
2024-06-10T19:44:37.432026Z ERROR update_base_branch: crates\gitbutler-tauri\src\virtual_branches.rs:152: error=Error(Access is denied. (os error 5)) project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:44:37.432037Z  INFO update_base_branch: crates\gitbutler-tauri\src\virtual_branches.rs:152: close time.busy=424ms time.idle=19.3µs project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:44:37.533287Z  INFO get_base_branch_data: crates\gitbutler-tauri\src\virtual_branches.rs:103: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:44:37.539372Z  INFO get_base_branch_data: crates\gitbutler-tauri\src\virtual_branches.rs:103: close time.busy=6.06ms time.idle=23.2µs project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:44:37.541081Z  INFO list_remote_branches: crates\gitbutler-tauri\src\virtual_branches.rs:452: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:44:37.546124Z  INFO list_remote_branches: crates\gitbutler-tauri\src\virtual_branches.rs:452: close time.busy=5.03ms time.idle=15.4µs project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:44:38.462619Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: new id=46469d3a-393a-450c-8f07-f5520ddf033e project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:44:38.463079Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: close time.busy=406µs time.idle=57.0µs id=46469d3a-393a-450c-8f07-f5520ddf033e project_id=46469d3a-393a-450c-8f07-f5520ddf033e fs_events=180 fs_events=180 ignored=0 ignored=0 git_noop=176 git_noop=176 git=0 git=0 project=0 project=0
2024-06-10T19:44:38.463109Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: new event=GitButlerOplogChange(46469d3a-393a-450c-8f07-f5520ddf033e)
2024-06-10T19:44:38.463577Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: close time.busy=451µs time.idle=17.0µs event=GitButlerOplogChange(46469d3a-393a-450c-8f07-f5520ddf033e)

Clicking the red Update button a second time seemed to work.

applying branch

Then, I tried applying an old virtual branch with a lot more files and changes in it, and got another error:
image

2024-06-10T19:52:50.290002Z  INFO get_remote_branch_data: crates\gitbutler-tauri\src\virtual_branches.rs:465: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e refname=Local(Refname { branch: "add-<redacted>", remote: None })
2024-06-10T19:52:50.295104Z  INFO get_remote_branch_data: crates\gitbutler-tauri\src\virtual_branches.rs:465: close time.busy=5.08ms time.idle=20.2µs project_id=46469d3a-393a-450c-8f07-f5520ddf033e refname=Local(Refname { branch: "add-<redacted>", remote: None })
2024-06-10T19:52:53.384827Z  INFO create_virtual_branch_from_branch: crates\gitbutler-tauri\src\virtual_branches.rs:73: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e branch=Local(Refname { branch: "add-<redacted>", remote: None })
2024-06-10T19:52:53.392619Z  INFO create_virtual_branch_from_branch:create_snapshot: crates\gitbutler-core\src\ops\oplog.rs:250: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e branch=Local(Refname { branch: "add-<redacted>", remote: None }) self=Project { id: 46469d3a-393a-450c-8f07-f5520ddf033e, title: "main", description: None, path: "C:\\Users\\<redacted>\\Documents\\main", preferred_key: SystemExecutable, ok_with_force_push: true, api: None, gitbutler_data_last_fetch: None, gitbutler_code_push_state: None, project_data_last_fetch: Some(Fetched { timestamp: SystemTime { intervals: 133625223150201638 } }), omit_certificate_check: None, snapshot_lines_threshold: None, use_new_locking: true }
2024-06-10T19:52:53.456294Z  INFO create_virtual_branch_from_branch:create_snapshot: crates\gitbutler-core\src\ops\oplog.rs:250: close time.busy=63.6ms time.idle=29.3µs project_id=46469d3a-393a-450c-8f07-f5520ddf033e branch=Local(Refname { branch: "add-<redacted>", remote: None }) self=Project { id: 46469d3a-393a-450c-8f07-f5520ddf033e, title: "main", description: None, path: "C:\\Users\\<redacted>\\Documents\\<redacted>", preferred_key: SystemExecutable, ok_with_force_push: true, api: None, gitbutler_data_last_fetch: None, gitbutler_code_push_state: None, project_data_last_fetch: Some(Fetched { timestamp: SystemTime { intervals: 133625223150201638 } }), omit_certificate_check: None, snapshot_lines_threshold: None, use_new_locking: true }
2024-06-10T19:52:53.776273Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: new id=46469d3a-393a-450c-8f07-f5520ddf033e project_id=46469d3a-393a-450c-8f07-f5520ddf033e
2024-06-10T19:52:53.776379Z  INFO set_project_active:watch:file monitor:handle debounced events: crates\gitbutler-watcher\src\file_monitor.rs:122: close time.busy=85.1µs time.idle=22.3µs id=46469d3a-393a-450c-8f07-f5520ddf033e project_id=46469d3a-393a-450c-8f07-f5520ddf033e fs_events=71 fs_events=71 ignored=0 ignored=0 git_noop=65 git_noop=65 git=0 git=0 project=0 project=0
2024-06-10T19:52:53.776523Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: new event=GitButlerOplogChange(46469d3a-393a-450c-8f07-f5520ddf033e)
2024-06-10T19:52:53.776745Z  INFO handle: crates\gitbutler-watcher\src\handler.rs:54: close time.busy=209µs time.idle=15.6µs event=GitButlerOplogChange(46469d3a-393a-450c-8f07-f5520ddf033e)
2024-06-10T19:52:58.171309Z ERROR create_virtual_branch_from_branch: crates\gitbutler-tauri\src\virtual_branches.rs:73: error=Error(failed to apply

Caused by:
    0: failed to checkout index
    1: failed rmdir - 'C:/Users/<redacted>/Documents/<redacted>/' is locked: Access is denied.
       ; class=Os (2); code=Locked (-14)) project_id=46469d3a-393a-450c-8f07-f5520ddf033e branch=Local(Refname { branch: "add-<redacted>", remote: None })
2024-06-10T19:52:58.171322Z  INFO create_virtual_branch_from_branch: crates\gitbutler-tauri\src\virtual_branches.rs:73: close time.busy=4.79s time.idle=43.4µs project_id=46469d3a-393a-450c-8f07-f5520ddf033e branch=Local(Refname { branch: "add-<redacted>", remote: None })
2024-06-10T19:52:58.173124Z  INFO list_remote_branches: crates\gitbutler-tauri\src\virtual_branches.rs:452: new project_id=46469d3a-393a-450c-8f07-f5520ddf033e

It did completely delete a couple files, as well as leave gitbutler in a weird state where it thinks that branch is applied but with 52 changes and deleted files because it wasn't actually able to update the filesystem.
image

Once gitbutler is at this point I can't unapply that branch or consistently revert changes. Sometimes I can use the new snapshotting feature to get me back somewhere usable but more often than not when I play around with it too much I end up having to delete the project and re-adding it.

Let me know if there's anything else I can test or if you need any more information.

@Byron
Copy link
Collaborator

Byron commented Jun 11, 2024

Thanks for the detailed account of what happens here, it's much appreciated and very useful!

It seems there are two different kinds of errors here - one is about failure to remove a directory during checkout, and the other one is a bit unclear as it only says 'access denied' happened in update_base_branch, without further trace or information.

And that is the error that interests me most (the one from updating workspace) as it might be related to the change that was done in the custom executable. That executable should prevent access denied errors when GitButler writes its own files, like projects.json, users.json, virtual_branches.toml and oplog.toml. All other sources of access-denied errors would remain unaffected (performance also wouldn't change thanks to it, that is expected).

@Byron Byron removed the feedback requested Feedback was requested to help resolve the issue label Jun 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working os:windows The Windows platform
Projects
None yet
Development

No branches or pull requests

7 participants