Folders and files disappear within ~10 minutes of creation, reappear after 30-60 minutes

[skander]

Hi,

Creating a seperate topic for this issue.

I’m not entirely sure if odrive is the culprit here, please assist in eliminating other factors.

We’re experiencing problems where newly created files and folders on the local storage (which uses odrive to sync to google drive) suddenly disappear within about 10 minutes of creation. 30 to 60 minutes after that, the files magically reappear.

Example:

The entirety of the path S:\__PROJECTEN__\2020\2020_KW4\ is set to sync via odrive to our remote storage (Google Drive).

Today, I locally created the path S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Test at around 16:10. I copied 9 jpg files (from outside of an odrive synced path) into this folder.

Around 16:20, I noticed that the folder \Test\ and its contents disappeared.

The lines in main.log are:

21 Oct 04:14:52PM INFO Successful Upload for S:/__PROJECTEN__/2020/2020_KW4/FLG Character/Aangeleverd/Test/invicibruuuu.jpg
21 Oct 04:14:52PM INFO Successful Upload for S:/__PROJECTEN__/2020/2020_KW4/FLG Character/Aangeleverd/Test/leon-man-2.jpg
21 Oct 04:19:38PM INFO Successful Delete Folder (Remote to Local) for S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Test

After this there is a gap of 10 minutes before odrive does anything else:

21 Oct 04:33:53PM INFO Successful Download for S:\__PROJECTEN__\2019\2019_KW4\[redacted]

(This is part of an ongoing recursive download, discussed in Odrive refusing to sync from remote to local storage)

No delete action was executed from the remote storage, at least not as I can see from the activity tab:

That’s just the last message of odrive creating the folder and copying the jpgs into it.

I expect the folder to locally reappear soon, as we’ve seen this happen a few times more in the past weeks. The problem was just so hard to chase because we haven’t been able to reproduce it, until now.

What could be the cause here? I also sent a diagnostic 30 minutes ago to be sure.

[Tony]

Hi @skander,
This is definitely odd.

The only reason odrive would delete something locally is if it was missing remotely. How long has this been happening?

Basically odrive requests a listing of a folder and determines if everything that comes back matches what we saw the last time we requested a listing of the folder. If there are differences, like an item no longer listed, it is counted as a delete and then reflected locally.

One possibility is that Google is experiencing delays in its back-end reflection via the API due to eventual consistency. We haven’t seen this to be a common issue, so it would definitely be unusual. If this did happen, though, newly uploaded items would upload successfully and then appear to be deleted after we take another look at the folder because the change has not yet propagated globally.

Are you able to reproduce this consistently?

One thing that you could do to check the same folder from the odrive web client, which will give you the listing as it is coming back from Google. It would be interesting to see if the webclient is also missing the folder when this occurs. This may be hard to catch, though, if it is an eventual consistency issue because we may be only talking about a window of a few seconds to catch it.

[skander]

Hi @Tony,

I know that this has been happening for a few weeks, maybe 2 months, but only rarely. I never was able to find out what was going on, as I only received an occasional anecdotal report from a colleague, and upon investigation always found all the files to be in place, with the colleague not being able to recall all the details of what had occured.

I was able to reproduce the problem after the last time my colleague notified me of it occuring again. Somehow it doesn’t happen consistently, and seemingly only in certain subfolders.

I just created another subfolder in S:/__PROJECTEN__/2020/2020_KW4/FLG Character/Aangeleverd/, locally, and put some random files in it:

S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Testmap lokaal aangemaakt 23-10 13u22

Another strange thing happened where the folder name got reset to Nieuwe map (New folder), even though the folder name already accurately got synced to the remote storage. I then locally changed the folder name again:

23 Oct 01:24:51PM INFO Successful Move (Local to Remote) for S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Nieuwe map to S:/__PROJECTEN__/2020/2020_KW4/FLG Character/Aangeleverd/Testmap 23okt 13u22

Resulting in 2 separate folders appearing on the remote storage.

Just tested it again. Created a folder locally, it gets synced instantly to google drive, then the folder is locally renamed to Nieuwe map again.

Drive file stream:

Local:

[Tony]

Hi @skander,
Hmm… this behavior also falls in-line with eventual consistency latency.

When you first create a new folder on Windows it will default to “New folder”. Since odrive will react right away to that, it is likely creating the new folder remotely before you’ve had a chance to rename it. Once you complete the rename from “New folder” to the new name, odrive will pick that change up and rename the remote folder to match. Now, if odrive then lists the remote folder and Google responds with the old name (“New folder”), it will think the folder was renamed back and reflect that locally.

This flow should be visible in the logs, however. For this particular example did you see a couple different operations for the same folder? I would expect something like:

1. Local to remote rename of “Nieuwe map” to “Testmap 23okt 13u22”
2. Remote to local rename of "“Testmap 23okt 13u22” to “Nieuwe map”
3. Local to remote rename of “Nieuwe map” to “Testmap 23okt 13u22”

On a side-note, I realized we are not logging out folder creations in the logs, so I will make sure that gets added in the next version.

Since you seem to have these odd reflection issues, I am going to think about what we can do to mitigate them for your particular situation. The instant reaction to local changes may not be optimal for your case and I think you may benefit from us disabling the local filesystem events and instead performing more frequent local scans to pick up local changes (we have an advanced option for this). This will create a longer time to pick up local changes, but I think it will reduce the churn you are seeing and help to combat some of these instances that look like eventual consistency latency (although I’m still trying to verify that).

[skander]

Thanks for the explanation @Tony

The only thing I do not get is how this behavior only seems to happen within certain folders. But I’m gonna test some more things to verify/falsify that.

Last test I did to see the log behavior went as followed:

1. I created folder Oct 26 1226 on the local storage.
2. I see Oct 26 1226 being created on the remote storage. (almost instantly)
3. I then see Oct 26 1226 then being renamed to Nieuwe map (2) (New folder (2)) on the local storage. (almost instantly)
4. I create another folder Oct 26 1231 on the local storage
5. I see the same process happening for that folder, but in the meantime:
6. Nieuwe map (2) is renamed back to Oct 26 1226 on the local storage

So what I understand of this is: When I create a new folder, it makes odrive relist the remote root folder (in other words, it “forces” the sync?) and then picks up the fact that there is no Nieuwe map (2) on the remote folder, but there is a Oct 26 1226.

All that is shown in main.log is this:

26 Oct 12:27:07PM INFO Successful Move (Local to Remote) for S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Nieuwe map (2) to S:/__PROJECTEN__/2020/2020_KW4/FLG Character/Aangeleverd/Oct 26 1226

26 Oct 12:27:18PM INFO Successful Move (Remote to Local) for S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Oct 26 1226 to S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd/Nieuwe map (2)

26 Oct 12:31:56PM INFO Successful Move (Local to Remote) for S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Nieuwe map to S:/__PROJECTEN__/2020/2020_KW4/FLG Character/Aangeleverd/Oct 26 1231

26 Oct 12:32:09PM INFO Successful Move (Remote to Local) for S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Oct 26 1231 to S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd/Nieuwe map

26 Oct 12:32:09PM INFO Successful Move (Remote to Local) for S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd\Nieuwe map (2) to S:\__PROJECTEN__\2020\2020_KW4\FLG Character\Aangeleverd/Oct 26 1226

I’m curious as to what happens with file discrepancies that happened in the meantime (lets say somebody worked remotely in Oct 26 1226 and somebody worked locally in Nieuwe map (2). What happens when the directory gets relisted and odrive syncs the “changes”? I’m afraid stuff might get lost in that case? Gonna try and test this too of course.

[skander]

What I noticed when creating another test folder Oct 26 1321:

After step 3 (local Oct 26 1321 folder gets renamed back to New folder), when I place stuff in the Oct 26 1321 remote folder, it gets synced to the local New folder, even though the folder names don’t match. The samen happens for remote -> local sync.

[Tony]

Hi @skander,
What makes this a little more confusing is that we aren’t currently logging the original folder create, so all you are seeing is the renames. Even so, we can infer the flow from the logs above.

In the Oct 26 1226 folder case this is what we can infer:

1. Nieuwe map (2) folder is created on the remote since odrive immediately picks this up when the right-click->New->Folder option is used in Explorer. (We are missing this event in the log, but it will be there in the next release)
2. at 12:27:07PM odrive now picks up the local rename from Nieuwe map (2) to Oct 26 1226 and syncs that to Google. This is the Successful Move (Local to Remote) event.
3. At 12:27:18PM odrive then performs a refresh of the remote folder and Google reports that the folder’s name is actually Nieuwe map. The assumption here is that the metadata change has not propagated fully for that object, so Google is sending back stale data.
4. at Oct 12:32:09PM odrive has performed another refresh and Google is now reporting the correct metadata, so Nieuwe map (2) is renamed back to Oct 26 1226. At the same time it is reporting stale metadata for the other folder Oct 26 1231 and saying its name is actually Nieuwe map

@skander

What happens when the directory gets relisted and odrive syncs the “changes”?

Since Google is object storage, odrive is actually tracking the remote objects based on their object IDs. This means that the local folder is associated with a remote object ID instead of a path. So, even though the metadata of the folder is changing, its ID is staying the same and remains the target.

[skander]

Thanks for the explanation @Tony!

Nice to learn about object storage and the way the tracking works. Good to know

Hopefully the adjustments in release 6756 will take care of most of the issues here.