Deleting or renaming directories when syncing xattrs or ownership causes empty dir tree to get "put back" by ST #9371
Comments
luckman212
added
bug
|
I suspect you're syncing/deleting settings of a running program, which is what causes the modifications and hence "resurrection" of the deleted files. This seems like a support issue more suited to the forum: forum.syncthing.net |
|
It's a subfolder of my Alfred workflows dir, but the files are not specifically settings or in any way belonging to Alfred. The bug also occurs regardless of whether Alfred is running or not. Further down the thread, I can reproduce the behavior with a completely separate non-related dir. |
|
I decided to try a database reset on both machines (not sure if it's required to do it on both side, so I did...) I used the API... Took about 12 minutes, and everything is re-synced. Will continue to monitor the situation. update: The db reset did not help. |
|
@calmh This is still weird. Been doing more testing today. I'm doing a "clean" test: a brand new folder that is OUTSIDE any application-related settings dir. Just a brand new folder called After a few moments, the files have synced to Machine-B. So far so good. Next, I select all and delete the files that were just created. About 10-15 seconds later, the folders mysteriously just come back. Sometimes all of them, sometimes only some of them. I can repeat this several times, the folders just will not stay deleted. Below is a screen recording showing this! In the debug logs, there are many messages like I don't know how to troubleshoot further but, something's definitely not right... May be related?
folders-reappearing1.mp4 |
|
Update 1: I compiled a custom build based on v1.27.3-rc.2+8f5d07b - just in case. No change... Update 2: I also experimented with lowering |
|
Here is where that log string is defined: syncthing/lib/model/folder_sendrecv.go Line 70 in 8f5d07b |
|
This is the block of code that generates the error: syncthing/lib/model/folder_sendrecv.go Lines 2028 to 2031 in 8f5d07b then later: syncthing/lib/model/folder_sendrecv.go Lines 2059 to 2061 in 8f5d07b |
|
So, generally speaking this doesn't happen, or we'd have a flood of complaints from everyone. As such, I'd suggest focusing on what might be different on your systems/setup that would trigger this. |
|
@calmh Believe me, I've been focusing on it for 3 days straight. I've fiddled with debug flags, written scripts to stream errors from the events API in realtime, reset my database, adjusted the None of it has helped. I am really stuck here, and starting to feel crazy. Syncthing's been working more or less flawlessly for me for many years now. The only thing I can think of that changed around the timeframe of when this started was I updated my 2 Macs to macOS 14.3. Could this be an OS-level bug? How could I even confirm that (short of reformatting my 2 Macs...) |
|
Yeah, but all of that is fiddling with Syncthing, and I'm thinking this works with the usual default Syncthing for almost everyone since forever, so that's not the right variable to tinker with. I'm more thinking along the lines of are you using a different filesystem, some odd hardware, some odd driver, some other sync- or backup software, does it happen in both directions or is it limited to one of the devices, if so does it happen with any other device you own, etc. |
Are there any additional debug options that could help track this down if I enable them? One other thought: could this be related to my Jan 30 morning update: I created an entirely new sync folder definition, left everything at defaults, and started it on both ends completely empty. Dropped in some files and waited for sync to reach 100%. Then, I deleted the folder contents on Machine-A. After ~1m the folders had returned back from the dead. I then scoured the advanced settings again, and saw the Jan 30 evening update: I spun up 2 brand new macOS VMs (mac1, mac2) completely isolated from each other and from the other systems involved in this bugreport. I did not do anything other than install Syncthing 1.27.2 on both of them, and connect them to each other. I created a new shared folder, using all default values for everything. I then repeated the original test: create a directory with around ~1100 files in it and ~150 directories. I waited for the sync to reach consensus. I then deleted the folder from mac1 and waited. The bug immediately reared its head again, a few of the folders quickly "snapped back". I repeated the test 2 more times to be sure. |
|
Yeah, you've certainly done your due diligence. I tried it a few times now on my macOS 14.3 M2 laptop, with two instances on the same machine but different directories etc, no snapbacks, so I still can't explain what you're seeing. Sorry. :/ |
Did you run the same script that generated the directories?
|
|
I did now, a whole bunch of times creating and removing the structure. In doing that I think I found another bug in the filesystem watcher (it seems to not trigger for items that were deleted, created, then deleted again, necessitating a manual or periodic scan to detect the remove...). I also got a couple of transient warnings on the receiving side ("directory has been deleted on a remote device but is not empty") which went away on retry. This could be an ordering issue or related to the above, perhaps. No putbacks, though. |
I'm not sure that's the "same" -- I will test it like that on my side. I suggest UTM for a free and simple way to spin up some macOS VMs for testing if you only have 1 Mac. Also, there's nothing special about that Python command that I ran to generate the files, I also tested by simply dragging a copy of the Syncthing macOS app bundle into the sync folder, and upon deleting that, it also snapped back, wirh empty orphan dirs left behind. Just asking again, are there any extra debug facilities that I can toggle on to help narrow down the cause of what I'm seeing here? |
|
The cause is in your initial post: |
Wow, thanks for discovering this. I think I've been hit by this bug quite a few times, and I always wondered what the culprit was. Had no idea how to reproduce, so I just kept restarting Syncthing to make the watcher work again. |
|
@calmh I think I may be making progress towards figuring this out. I had a theory that Spotlight was "doing something" to the files shortly after creation. I added an exclusion for the dir that I was syncing in Syncthing and re-ran the tests. No problem! No "snapbacks"! I then made a small test script to dump the timestamps to a file, pause 10s and dump them again, and diff the results: #!/bin/zsh --no-rcs
DIR=$HOME/hello_world
echo "v1"
find -s "$DIR" ! -path '*/.stversions/*' -exec stat -f%a,%m,%c,%B%t%N {} \; >/tmp/v1
echo "sleeping for 10s"
sleep 10
echo "v2"
find -s "$DIR" ! -path '*/.stversions/*' -exec stat -f%a,%m,%c,%B%t%N {} \; >/tmp/v2
echo "diff:"
diff /tmp/v{1,2}When I ran this immediately after the pip install command that adds the files, I saw that the For example I think Syncthing counts a change in the IF this is what is happening, I'm not sure I understand the merit of considering merely accessing a file as a "change", but in case that's a long-standing or breaking change, I wonder is there some advanced config flag to tell ST to ignore changes in atime and only consider the other timestamps like update: Further tests are now conflicting with this finding: even when adding an exclusion in Spotlight to my original systems, I am still seeing this atime discrepancy 6-8 seconds after the files are created. Not sure whether that's a red herring, or if Syncthing even takes atime into consideration at all... |
|
This is getting weirder. It also affects renames. If I have a folder called st_rename1.mp4 |
luckman212
changed the title
|
I'm desperate. Anything else I can do here to try to track this down? I just enabled the following extra debug modules on both machines
...and ran this quick test
Here's are log outputs of The deleted folders had all snapped back... |
|
Looking at this, there are a couple of oddities. We take an example failed remove: This gets scanned a little later, so we can see what differences we saw: Spoiler: no relevant differences, or shouldn't be. The modtime differs, but we expect that since we touched children, and we never care about mtime of directories for this reason (nor atime for anything ever). Also the InodeChangeTime differs. I don't know off hand whether that's expected just based on having deleted children, but we don't normally care about that anyway... except... Hang on, we're syncing extended attributes? That wasn't mentioned so far. In that case we do care about the inode change time, because it indicates (or can indicate) a change in xattrs. I wouldn't be surprised if a bunch of xattrs get set automatically in the background by all kinds of things, in this case apparently a provenance attribute was set and we're configured to ignore it... |
|
Thanks for looking @calmh. Hmm yes I am syncing (some) xattrs but I've had them set like that for a looong time and never seen this behavior before. So 
I'll repeat the test and before deleting, I'll check the xattrs on both sides to see what they look like. |
|
Still completely stumped here. I just double checked for any errors in my I retested, checking the xattrs that were set on the folders before and after the deletion/snapback. The only xattr present on the folders BEFORE deletion was Slightly redacted
|
|
Just want to mention: when I did the isolated test with 2 fresh VMs a couple of days ago, the folder was set up with 100% default values (no xattr syncing) and I was still getting the snapbacks. edit: I just spun up 2 macOS 14.2.1 VMs and am about to repeat the test again to see if this is a regression caused by 14.3 somehow. edit 2: Finished the testing. No issues on the 14.2.1 VMs! So I'm now strongly leaning towards this being some kind of bug or new behavior in macOS 14.3. edit 3: I updated my 2 machines to macOS 14.4 dev I don't have access to the granular statistics that feed data.syncthing.net but I wonder, how large is the intersection of users who are (a) using macOS 14.3 and (b) happened to notice this somewhat rare condition? I see darwin-arm64 is only 3223 users, so I could imagine that it's only a few hundred users at most running 14.3... maybe I'm just the first to notice? |
|
Also, here's a new error I've never seen before:
|
|
Well, after running ...and seeing a handful of xattrs on my directories that I've never seen before e.g. ...I decided to try disabling xattr syncing altogether until I can figure out what's going on. After doing that, the folder deletions seem to be working again. Still does not explain the behavior I'm seeing. |
|
Compiled a macOS bundle with 1.27.3 as a test. Still bugged for me. I don't want to leave xattr sync off long term because I do use tagging and comments in my workflows. Anywhere to go from here troubleshooting wise? |
|
I updated my previous post with a logging function. Also published it as a gist: |
|
This issue thread has become somewhat of a monstrosity. Is there anything actionable here? I feel like I've exhausted the resources I have: collected as much info, logs, scripts, repro steps, configs, screenshots, recordings, etc as I know how to do. Sadly, diving head first into the Go code is over my head, otherwise I would have done that instead of spending the last 2 weeks tacking comments on here. I'm surprised at how few people seem to have noticed this bug. It must be a vanishingly small intersection of Syncthing users who are (a) using macOS 14.3+, (b) syncing xattrs, and (c) happened to notice that the folders they deleted are resurrecting themselves. Is there anything else I can do that could be useful in tracking down the source of this bug? Should I report it to Apple? What about setting up remote access to 2 Macs that are configured to reproduce this behavior? |
|
If you were to dive into the Go code, I would start with the machine where the folders are created then deleted. We have already dug a bit into the code for the downstream machine. Specifically I would look at 2 things. I would look at how and if MacOS modifies the extended attributes when you delete the files/folders and I would look at how the Go code handles both deletion and modification of extended attributes. Knowing sync software, it is possible that MacOS is modifying the files at the same time it is deleting them, creating a race condition for sync programs. EDIT: A third thing I might look at it if I were you is what method MacOS uses to remove files via the GUI. It is possible that they are moving the head of the file tree (root directory) to a temporary trashcan before deleting the files as opposed to removing them recursively. In short, what you are looking for is possible race conditions. I lack the same environment you have by a long shot. I was here to evaluate syncthing and other software as a replacement for my NAS. So I don't even have syncthing running on my lab, much less a Mac. I'm sure a similar cases exist for other devs here. Other considerations usually involve unpaid time: the devs may plan to look at this far later (which in your case may not be ideal). The way to get around that is try your best to patch it yourself.
As for reading Go code, I would take snippets you don't understand and provide them to GPT (or another generative AI) along with context and where you got the code from to have GPT explain it to you more simply. |
|
By the looks of it, this actually isn't a MacOS-related/only issue... I've just tried it between Ubuntu 20.04 (I have to admit as vm on a MacOS host) and some Docker container on a Bookworm host (rpi 5) -> it does happen too (v1.27.2, Linux (64-bit ARM Container) <> v1.27.2, Linux (64-bit ARM)). In any way, it's not a MacOS<>MacOS only issue. Just enable sync extend attributes on both sides, and the dirs (as long as they're not empty) will reappear (empty) after deleting or renaming them. |
luckman212
changed the title
|
Could the bug actually be in the filesystem watcher module https://github.com/syncthing/notify ? I notice that hasn't been updated in ~3 years. And during manual compilation, I get warnings about |
|
Hi,
Hi, You're not alone ;-) I've got a similar config :
The trouble is the same :
I use macOS color tag intensively to check progress in my work, so extended attributes a checked to reflect those changes. I've just made new tests :
|
|
I've been playing around with the tools I mentioned above. The "simplest" so far seems to be FSMonitor. Below are several screenshots that show the filesystem events captured on both the sender and receiver during the deletion of the folder called new that is within the test123 Sync folder that I've been using to test: 
Mac A (sender)
The screenshot above shows that a split-second after deleting the Mac B (receiver)
It's also interesting to me that on the Receiver (MacB), there are delete events for all the files 1-20, but no delete event for the new directory itself. |
|
FSMonitor wasn't giving me enough detail, so I went back to working directly with Syncthing's own event logging via the API with my stfwatch script. I created another script, which I used to generate the video below. It uses It seems that it bounces between and until finally at the end when it's Also of note are the strange jdiff1.mp4edit: if anyone wants a copy of this json-diff script, I posted a gist: |
luckman212
changed the title
|
...so if i understand correctly, v1.27.5 has been released, however not yet for macOS ? |
|
@notDavid Right, should be soon. I saw @xor-gate tagged a 1.27.5 pre-release yesterday, but as of now there's no binary attached to it yet... |
|
@luckman212 no pressure, Syncthing macOS is a sub project and needs semi-manual actions to upgrade the bundle syncthing instance. And is done on best effort base. It was pending in my mailbox. And the release has finaly happend. Have fun! |
|
I'm still amazed at how much work you put into this @luckman212 considering that you started as a non-go-developing end-user |
Does your log mention database corruption?
No
Versions
1.27.21.27.3 macOS Bundle, also tested on v1.27.4-rc.1Setup
Trash CanSimple file versioning (also tested with File Versioning disabled, makes no difference)Issue
In the last few days, while working in one particular subfolder of my single Sync directory, I experienced a situation where a deleted folder from machine A (that was present and fully synced between my 2 computers) almost immediately re-appears.
The error message
syncing: delete dir: file modified but not rescanned; will try again laterseems to repeat ad infinitum in the logs below.The only way I "solved" this was to very quickly delete the folder at the same time from both machines. But, if I re-create that folder and then delete it from machine A or B independently, the problem resurfaces.
The clocks are set correctly on both machines.
Deleting the directory via Terminal
rm -rf ./whatever/behaves the same as trashing it via Finder.probably related forum thread: https://forum.syncthing.net/t/deleted-folders-keep-re-appearing/19290/28
update: PR submitted
#9424... and now an updated one #9430Logs
(click to reveal)
The text was updated successfully, but these errors were encountered: