Glitch on Sync/Mirror <Item not existing>

[jpgill86]

Thanks for the guidance Zenju!

I decremented my page token just enough to get changes that are timestamped before today, for a total of 20 changes. I've attached the JSON output.

There is a suspicious string of changes with identical timestamps from earlier today (2021-05-06T16:15:11.188Z). I'm 99% sure this was a few hours before I used FFS today (I understand this is UTC time and have accounted for time zones and daylight savings time), but one of these changes was to sync.ffs_db, so perhaps I'm mistaken. The other file changes with that timestamp correspond exactly to my list of files reported by FFS as missing from the Shared Drive (except for one extra file listed among the changes that is not flagged by FFS). All have the "removed" parameter set to false.

Since FFS seems to think that the files don't exist on the Shared Drive (rather than that they were deleted -- I assume in that case a Two-Way sync would suggest deleting my local files), would it be better to query for the Shared Drive's file list, to see if the files are unlisted? Is that a plausible way that FFS would think the files don't exist? Or does it only comb the change list? That would seem like an inefficient way to determine if a file was present or not, since you would have to search the entire history.

[Zenju]

That's a good start. A few remarks:

You also need to set the "fields" parameter as mentioned earlier. Otherwise you won't get all the detail fields that FFS is seeing. For example, there's not only the "removed" field, but also a "trashed" field, and a "parents" field (removing a parent is similar to deletion).

Also. An item can be deleted implicitly when one of its parent folder is deleted. So it's important not only to search for a particular item ID in the changes list, but also all the IDs of parent elements and see what's changed for them.

[jpgill86]

You also need to set the "fields" parameter as mentioned earlier.

Oops! >_<

Here's another JSON output, this time with the fields you listed. I extended your list a bit by adding fields that appeared among the default fields, so that the new JSON output is a superset of the old (in particular, the "time" field needed to be added to see that suspicious timestamp). I also added "createdTime". For the record, these are all the fields I used:

kind,nextPageToken,newStartPageToken,changes(time,type,kind,changeType,removed,fileId,file(kind,id,trashed,name,mimeType,ownedByMe,size,modifiedTime,createdTime,parents,shortcutDetails(targetId),teamDriveId,driveId),drive(name))


The new fields that appear in this version of the JSON output but not the first are "createdTime", "trashed", "parents", "modifiedTime", and "size". For every one of the changes with the suspicious timestamp mentioned earlier, "trashed" is set to false. Nothing else stands out as unusual to me.

[jpgill86]

Also. An item can be deleted implicitly when one of its parent folder is deleted. So it's important not only to search for a particular item ID in the changes list, but also all the IDs of parent elements and see what's changed for them.

By this do you mean that, although the new JSON output I just posted has "trashed" set to false for all changes with the suspicious timestamp corresponding to files indicated by FFS as missing, their parents (or their parents' parents, etc.) might have been trashed? Do I need to perform a file query for each parent?

Here's a screenshot of the bad two-way comparison in FFS, which might make deciphering the JSON a little easier. Again, all of these files are in fact still on the Shared Drive, though FFS seems to think they are not.

ffs-gdrive-bad-comparison.PNG (335.62 KiB) Viewed 47946 times

[jpgill86]

By the way, I have some familiarity with the Google Drive API already. I created a Python application with a feature that uses the API (via PyDrive2) to download files by path, rather than file ID, so I know a bit about traversing the file tree.

Anyway, given some specific details on how FFS decides when files are missing from the server, perhaps I would be able to do some deeper digging.

[Zenju]

The source is in \Source\afs\gdrive.cpp
After an initial traversal, FFS *only* uses Google's change notifications ("list") to update the file state.

So whatever the reason why a file is missing (*), it must have been communicated via change notifications.

*) To be verified: how did you conclude the file is really *existing* at this Google Drive path? It's possible FFS is right, and the file was moved somewhere else.

[Zenju]

Having a look at the first file:

<shared drive: 0AFnJZoCV2a6RUk9PVA>
|
-> "Data" <folder: 1RpF7RgJmgYUQ-6r5R3IxoMRnzM5YMeK->
    |
    -> "Animal-10_35g_2021-01-18" <folder: 1eIGNDUMJCr-E0AneocuL-8G8ivUojddD>
        |
        -> "Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" <file: 12dG_uscX47wmEewXS1cvl7KK3Y6mxKKz>


You're syncing against the "Data" folder of your shared drive.
According to the change notifications you provided above, the path on Google drive is:

<shared drive root>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv

Can you check the IDs of the parent folders and the .csv file on your Google Drive account and see if they match?

[Zenju]

There's also a removed file or folder (ID 1Hb4S8DDn0kEleVem3n4-pul4FGobhAhx) at "2021-05-06T23:48:19.720Z", wondering what this was..

[jpgill86]

*) To be verified: how did you conclude the file is really *existing* at this Google Drive path? It's possible FFS is right, and the file was moved somewhere else.

I think I can verify that files with these names exist at these paths by browsing to the containing folder in Google Drive in my browser:

gdrive-browser-10.PNG (320.99 KiB) Viewed 47865 times

The parent (folder) ID is visible in the address bar. I can check the file ID by right-clicking and choosing the "Get link" option:

gdrive-browser-10-2.PNG (293.76 KiB) Viewed 47865 times

However, if I were to double-click on the file to open it, it would display as expected (a preview of the spreadsheet would be displayed), and then the file would drop out of the list of files reported by FFS as missing from the Shared Drive. Could we take advantage of this odd effect by looking at the change list right after I open a file, causing it to be cleared from the list?

Having a look at the first file:

<shared drive: 0AFnJZoCV2a6RUk9PVA>
|
-> "Data" <folder: 1RpF7RgJmgYUQ-6r5R3IxoMRnzM5YMeK->
 |
 -> "Animal-10_35g_2021-01-18" <folder: 1eIGNDUMJCr-E0AneocuL-8G8ivUojddD>
 |
 -> "Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" <file: 12dG_uscX47wmEewXS1cvl7KK3Y6mxKKz>


You're syncing against the "Data" folder of your shared drive.
According to the change notifications you provided above, the path on Google drive is:

<shared drive root>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv

Can you check the IDs of the parent folders and the .csv file on your Google Drive account and see if they match?

As you can see from the screenshots above, the IDs for the CSV file and the "Animal-10_35g_2021-01-18" folder match those that appear in the changes list. I also checked the "Data" folder ID and shared drive root ID, and these also match.

There's also a removed file or folder (ID 1Hb4S8DDn0kEleVem3n4-pul4FGobhAhx) at "2021-05-06T23:48:19.720Z", wondering what this was..

I'm not certain, but I think that was something I did intentionally while composing a post for this thread on Thursday. I may have created and then deleted a file as a test. That change does not appear in my first JSON file (the one with too few fields), so it must have been something I did before generating the second.

The source is in \Source\afs\gdrive.cpp
After an initial traversal, FFS *only* uses Google's change notifications ("list") to update the file state.

So whatever the reason why a file is missing (*), it must have been communicated via change notifications.

Gotcha, I think I get it now. Is it possible my JSON file does not go far back enough in time for us to see the most relevant changes, and the changes with the suspicious timestamp that I've been focusing on are a red herring?

[Zenju]

I think I can verify that files with these names exist at these paths by browsing to the containing folder in Google Drive in my browser:

Looks good. The file IDs and parent-child folder relations match what's listed in the change notifications.
Considering that for example the item "Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" is not removed, not trashed, and it's parents structure is intact, it should be listed as existing on the right hand side of download/file.php?id=1900&sid=1510e118cfc2f5ee3fc8a33dd166cc2c

Except (for completion): The screenshot doesn't explicitly show that the right hand side really is the shared drive, and the left side is the local drive.

However, if I were to double-click on the file to open it, it would display as expected (a preview of the spreadsheet would be displayed), and then the file would drop out of the list of files reported by FFS as missing from the Shared Drive.

Double-click where? In FFS or in Google Drive? Double-clicking an item in FFS will open the browser and navigate to Google Drive without preview.

Could we take advantage of this odd effect by looking at the change list right after I open a file, causing it to be cleared from the list?

I'm assuming by "cleared from the list" you mean it is shown as existing in FFS when you click on the equal(=) button? This means FFS has received new change notification as a result of your double-clicking.


What kind of change notifications? We can find out!
1. https://developers.google.com/drive/api/v3/reference/changes/getStartPageToken
2. double-click...
3. getStartPageToken again, this should yield a new token => this shows that indeed changes occurred
4. retrieve list of changes by entering the token from 1.: https://developers.google.com/drive/api/v3/reference/changes/list

Is it possible my JSON file does not go far back enough in time for us to see the most relevant changes,

I don't think so. The changes shown in viewtopic.php?t=7827&start=30#p29629 should be enough for FFS to assume an existing file at <shared drive root>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv

and the changes with the suspicious timestamp that I've been focusing on are a red herring?

The change notifications at 2021-05-06T16:15:11.188Z match exactly the 14 items shown missing on your screenshot download/file.php?id=1900
This could be more than a coincidence.

Also noteworthy:
• there's an "Animal-10_35g_2021-01-18 002.axgd" file also changed at 2021-05-06T16:15:11.188Z, not shown on your screenshot => maybe it is one of the equal ("=") files? Or excluded via filter?

• the two files "Animal-10_35g_2021-01-18 001.axgd" and "Animal-10_35g_2021-01-18 002.axgd" are existing twice on your screenshot: download/file.php?id=1908

[Zenju]

Current working theory:

I believe Google Drive is delaying the sending of change notifications. That could explain all these symptoms, but this theory first needs to be verified:

A delay of sending change notifications is possible when manually deleting a file via the browser interface. It can take a while (sometimes multiple minutes!) before FFS "sees" the deletion, even though it is polling Google Drive change notifications ("list") repeatedly. I've seen this Google Drive "delay" myself (... it could almost be called a bug...), and also:

After getting that to work, the file comparison helped me realize that some files needed to be deleted from the Shared Drive; they were mistakenly placed there by a collaborator. As expected, these files were showing in my two-way comparison as being ready to be copied locally. Since I did not want to keep them, I deleted them in the Shared Drive manually, but when I re-ran the comparison, it still claimed these deleted files were in the Shared Drive, ready to be synced. I tried emptying the Shared Drive's trash, but that made no difference.

So maybe in the current case with shared drives, access to some files is lost temporarily. Google Drive API's "list" will report deletions, FFS sees these changes and dutifully removes these files from its Google Drive database (.db) in the "GoogleDrive" subfolder.
After a while, access is restored back to normal, but the Google "list" API does not report this change (yet), which one could call a bug (or Google could call it a "performance optimization"). Only *after* you physically access a file, the "list" API finally returns the list of change notifications that make the files reappear. Evidence:

Intent on getting a file ID, as Zenju suggested, I clicked on the files in my browser to open them, so that I could extract the ID from the URL. Not only did this update the last opened date on Google Drive, but it also fixed the comparison in FFS, so that the files were no longer reported as deleted. I did this for the two files one at a time, and they were fixed one at a time.

[t0ma5]

what would be the best work-around for this problem?

[jpgill86]

Except (for completion): The screenshot doesn't explicitly show that the right hand side really is the shared drive, and the left side is the local drive.

A fair point! I was lazy and cropped out the private information, rather than blurring it. Here is another version showing that the local and remote sources were on the left and right, respectively, and that the comparison mode was two-way.

ffs-gdrive-bad-comparison-2.PNG (377.88 KiB) Viewed 47831 times

Note that there is one fewer file here compared to the previous screenshot. This is because I intentionally caused the animal 13 file to drop out of the list by opening it on Google Drive in my browser.

However, if I were to double-click on the file to open it, it would display as expected (a preview of the spreadsheet would be displayed), and then the file would drop out of the list of files reported by FFS as missing from the Shared Drive.

Double-click where? In FFS or in Google Drive? Double-clicking an item in FFS will open the browser and navigate to Google Drive without preview.

I meant in Google Drive, from a web browser, as could be done from this screen: download/file.php?id=1908. Doing so will open a preview of the CSV file, like this:

preview.PNG (151.95 KiB) Viewed 47831 times

Opening this preview will cause the file to drop out of FFS's list of files needing to be synced, suggesting it has become aware of the file's presence on Google Drive.

Could we take advantage of this odd effect by looking at the change list right after I open a file, causing it to be cleared from the list?

I'm assuming by "cleared from the list" you mean it is shown as existing in FFS when you click on the equal(=) button?

Yes, that's right. Here's the animal 13 file, previously thought by FFS to be in need of copying to the Shared Drive, but now recognized as being there already after I opened the CSV preview in my web browser:

animal-13-now-exists.PNG (432.65 KiB) Viewed 47831 times

This means FFS has received new change notification as a result of your double-clicking. What kind of change notifications? We can find out!
1. https://developers.google.com/drive/api/v3/reference/changes/getStartPageToken
2. double-click...
3. getStartPageToken again, this should yield a new token => this shows that indeed changes occurred
4. retrieve list of changes by entering the token from 1.: https://developers.google.com/drive/api/v3/reference/changes/list

An excellent experiment. Here is the entirety of what I got after double-clicking on the animal 15 file:

{
 "kind": "drive#changeList",
 "newStartPageToken": "13230",
 "changes": [
  {
   "kind": "drive#change",
   "type": "file",
   "changeType": "file",
   "time": "2021-05-11T00:55:28.000Z",
   "removed": false,
   "fileId": "1t7fwQXTzyP4gADxqyncWnrLm9YfomSIF",
   "file": {
    "kind": "drive#file",
    "id": "1t7fwQXTzyP4gADxqyncWnrLm9YfomSIF",
    "name": "Animal-15_61g_2021-02-12 001 EPOCH-ENCODER.csv",
    "mimeType": "text/csv",
    "trashed": false,
    "parents": [
     "1V6Dx7X9cUc136ZOWr3erY-lc0k8L_x8Y"
    ],
    "createdTime": "2021-04-21T20:41:01.142Z",
    "modifiedTime": "2021-04-21T20:35:47.000Z",
    "teamDriveId": "0AFnJZoCV2a6RUk9PVA",
    "driveId": "0AFnJZoCV2a6RUk9PVA",
    "size": "5397"
   }
  }
 ]
}


The timestamp "2021-05-11T00:55:28.000Z" correctly identifies the time when I did the double-clicking. Other than that, this one change list entry is identical to the one found in my previously shared JSON output, which had that suspicious timestamp.

Upon opening the preview, the Last Opened timestamp was updated:

animal-15-preview-opened-time.PNG (249.62 KiB) Viewed 47831 times

I guess the change list entry copied above refers to an update to the Last Opened timestamp. However, this JSON output doesn't make that clear. Are there perhaps other fields I can query to show that this change list entry is describing an update to the Last Opened time? And if I query the same fields for the older suspicious entries, might we find out what caused them?

Also noteworthy:
• there's an "Animal-10_35g_2021-01-18 002.axgd" file also changed at 2021-05-06T16:15:11.188Z, not shown on your screenshot => maybe it is one of the equal ("=") files? Or excluded via filter?

I can see that it is indeed one of the equal files. It is not excluded by a filter. For whatever reason, this one file out of all those with that suspicious timestamp is correctly identified by FFS as being present on the Shared Drive.

• the two files "Animal-10_35g_2021-01-18 001.axgd" and "Animal-10_35g_2021-01-18 002.axgd" are existing twice on your screenshot: download/file.php?id=1908

Yes, you are correct. My situation is not as well controlled as t0ma5's: I am not the only person with access to this Shared Drive, and others mistakenly put duplicates of those files there. However, I obsessively micromanage this Shared Drive, and on the rare occasions when others make changes to it (always via their web browsers, and never using FFS, I'm pretty sure) they usually think to notify me. I regularly use FFS with WinMerge to help me monitor and track unannounced changes (though in this case FFS has blind spots for duplicated files).

It's possible I may not have the whole story on everything that has been done in this drive. For example, someone else's activity might be tied to the suspicious timestamps (and I don't expect any of them to have recollections that I could query now; perhaps the API would know who the actor was?). Regardless, I think we are in agreement that it seems FFS should know that these files already exist on the Shared Drive, since they appeared in the changes list. Would you agree?

Current working theory:

I believe Google Drive is delaying the sending of change notifications. That could explain all these symptoms, but this theory first needs to be verified:

A delay of sending change notifications is possible when manually deleting a file via the browser interface. It can take a while (sometimes multiple minutes!) before FFS "sees" the deletion, even though it is polling Google Drive change notifications ("list") repeatedly. I've seen this Google Drive "delay" myself (... it could almost be called a bug...), and also:

After getting that to work, the file comparison helped me realize that some files needed to be deleted from the Shared Drive; they were mistakenly placed there by a collaborator. As expected, these files were showing in my two-way comparison as being ready to be copied locally. Since I did not want to keep them, I deleted them in the Shared Drive manually, but when I re-ran the comparison, it still claimed these deleted files were in the Shared Drive, ready to be synced. I tried emptying the Shared Drive's trash, but that made no difference.

I agree, a delay in notifications could have been responsible for that particular issue back in December, where deletions performed manually in Google Drive were not immediately reflected in FFS. Perhaps if I had waited longer, the comparison would have updated properly.

So maybe in the current case with shared drives, access to some files is lost temporarily. Google Drive API's "list" will report deletions, FFS sees these changes and dutifully removes these files from its Google Drive database (.db) in the "GoogleDrive" subfolder.
After a while, access is restored back to normal, but the Google "list" API does not report this change (yet), which one could call a bug (or Google could call it a "performance optimization"). Only *after* you physically access a file, the "list" API finally returns the list of change notifications that make the files reappear. Evidence:

Intent on getting a file ID, as Zenju suggested, I clicked on the files in my browser to open them, so that I could extract the ID from the URL. Not only did this update the last opened date on Google Drive, but it also fixed the comparison in FFS, so that the files were no longer reported as deleted. I did this for the two files one at a time, and they were fixed one at a time.

It seems to me that this scenario would require an access restoration notification to be "delayed" indefinitely (never notified). If the delay was only a few minutes, I think the FFS comparison would need to run during that narrow window of time for FFS to strike the files from its database, which seems unlikely in my case; or have I misunderstood?

Still, suppose FFS has struck files from its database. Why then does FFS seem to ignore the recent entries with the suspicious timestamps, which imply the files exist but don't indicate they were trashed?

Perhaps it's not important, but I'm curious: Where is this "GoogleDrive" subfolder, containing the Google Drive database (.db)? I use Windows, so I looked in %APPDATA%\FreeFileSync but didn't find it there. Would there be any use to inspecting it more closely?

[jpgill86]

Perhaps it's not important, but I'm curious: Where is this "GoogleDrive" subfolder, containing the Google Drive database (.db)? I use Windows, so I looked in %APPDATA%\FreeFileSync but didn't find it there. Would there be any use to inspecting it more closely?

Oops, I'm a dummy and checked %APPDATA% on the wrong computer... I found the database file when I looked on the computer that actually does the syncing. 🤦‍♂️

[Zenju]

A fair point! I was lazy and cropped out the private information, rather than blurring it. Here is another version showing that the local and remote sources were on the left and right, respectively, and that the comparison mode was two-way.

Thanks for clarifying! The fact that you're using "two-way" which creates a different DB file (sync.ffs_db) doesn't matter here, because this DB is only relevant for determining the sync directions, *not* current existence of files/folders.

Note that there is one fewer file here compared to the previous screenshot. This is because I intentionally caused the animal 13 file to drop out of the list by opening it on Google Drive in my browser.

Alright. It's good you're keeping the test case unchanged as much as possible.

An excellent experiment. Here is the entirety of what I got after double-clicking on the animal 15 file:

I'm wondering if FFS is also at "newStartPageToken": "13230". I believe it is, but I'll have to see the contents of the Google Drive .db file just to make sure.

So question is why then did the changes list you provided in viewtopic.php?t=7827&start=30#p29606 not lead FFS to conclude existence?

I just noted a peculiarity: The order of change notifications for the first example (it was a great idea you included changes(time)!) and the large time gap between them which implies they were caused by separate actions:

2021-05-06T16:15:11.188Z <shared drive>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv
2021-05-06T19:59:07.974Z <shared drive>/Data/Animal-10_35g_2021-01-18
2021-05-06T23:48:25.655Z <shared drive>/Data
2021-05-06T23:48:25.655Z <shared drive>


There's no way that FFS would conclude "Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" missing at 2021-05-06T16:15:11.188Z.

But what if the real list of changes looked like:

2021-05-06T16:15:11.188Z <shared drive>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv

2021-05-06T19:59:07.000Z REMOVED <shared drive>/Data/Animal-10_35g_2021-01-18

2021-05-06T19:59:07.974Z <shared drive>/Data/Animal-10_35g_2021-01-18
2021-05-06T23:48:25.655Z <shared drive>/Data
2021-05-06T23:48:25.655Z <shared drive>


...where REMOVED could also be some temporary loss of access!? You're on a Shared Drive after all.

In this case Google would automatically condense the two change notifications

2021-05-06T19:59:07.000Z REMOVED <shared drive>/Data/Animal-10_35g_2021-01-18
2021-05-06T19:59:07.974Z <shared drive>/Data/Animal-10_35g_2021-01-18


into a single one representing the latest state

2021-05-06T19:59:07.974Z <shared drive>/Data/Animal-10_35g_2021-01-18


How would FFS react to this if a comparison is run right after "2021-05-06T19:59:07.000Z REMOVED"? It would remove the item "<shared drive>/Data/Animal-10_35g_2021-01-18".
But also do one more thing: it would remove the parent folder association for the "<shared drive>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" item, not waiting for the expected change notifications of "Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" that would report a removed parent folder. This second and usually expected change notification does not occur in this example, because the folder is not permanently deleted. Therefore FFS's reaction would be a bug.

If this is what has happened, it would explain all the symptoms! I find it plausible that Google Drive could have temporarily reported a folder deletion/access loss just to have it restored shortly after *without* also sending a change notification for each of its this folder's child elements that the parent folder was removed. I've seen similar behavior with Google Drive's change notifications before. This could be considered a logic bug on Google's side. But anyway, FFS should be robust enough to handle this kind of inconsistency.

To verify this theory, I'll have to have a look at the content of your Google Drive .db file. I hope you haven't done any changes to your Google Drive, so that it is in a state that matches your screenshot download/file.php?id=1911&sid=747fdbe97e53646a93e785f2da98d13f

I guess the change list entry copied above refers to an update to the Last Opened timestamp. However, this JSON output doesn't make that clear. Are there perhaps other fields I can query to show that this change list entry is describing an update to the Last Opened time? And if I query the same fields for the older suspicious entries, might we find out what caused them?

The metadatum that triggered the change notification is probably "viewedByMeTime" https://developers.google.com/drive/api/v3/reference/files

And if I query the same fields for the older suspicious entries, might we find out what caused them?[/b]

Possible. Instead of explicitly specifying the fields you want, I believe you can also set "*" to get all the data available in the change notifications. But more interesting than changes for the files themselves is what happened after that to their parent folders, e.g.:

<shared drive>/Data/Animal-10_35g_2021-01-18  ID: 1eIGNDUMJCr-E0AneocuL-8G8ivUojddD
<shared drive>/Data                           ID: 1RpF7RgJmgYUQ-6r5R3IxoMRnzM5YMeK
<shared drive>                                ID: 0AFnJZoCV2a6RUk9PVA


I regularly use FFS with WinMerge to help me monitor and track unannounced changes (though in this case FFS has blind spots for duplicated files).

The internal model of FFS closely follows that of Google Drive, so these duplicate file names are accounted for. But this concept obviously doesn't fit with normal file system rules that FFS represents on its GUI, so it shows only a single line item. But were you to interact with such a line item in any way, FFS would issue errors about the underlying ambiguity of the file path.

I agree, a delay in notifications could have been responsible for that particular issue back in December, where deletions performed manually in Google Drive were not immediately reflected in FFS. Perhaps if I had waited longer, the comparison would have updated properly.

The delay I've seen is minutes at most, so this theory can probably be dismissed. Still it's really unfortunate that Google Drive can delay change notifications for such a long time, while their web interface on the other hand already shows the more recent state.

Still, suppose FFS has struck files from its database. Why then does FFS seem to ignore the recent entries with the suspicious timestamps, which imply the files exist but don't indicate they were trashed?

I believe the items are still existing in FFS's Google Drive .db files, just the association with their parent folder is severed, thous they're shown as not existing "at this path", but orphaned items (in FFS's view).

[Zenju]

If this is what has happened, it would explain all the symptoms! I find it plausible that Google Drive could have temporarily reported a folder deletion/access loss just to have it restored shortly after *without* also sending a change notification for each of its this folder's child elements that the parent folder was removed. I've seen similar behavior with Google Drive's change notifications before. This could be considered a logic bug on Google's side.

I might be wrong here. Losing access to a folder but NOT to its contained files actually may be something that the Google Drive model simply allows (unlike normal file systems). Sure, the child items will be orphaned, but they should not be considered deleted.
Technically, FFS correctly considers them orphaned, too, it's just that Google won't send any change notifications for the child items again when parent folder access is restored. Additionally, orphaned items aren't persisted in the .db file by FFS.

[jpgill86]

I think I've found a way to reliably reproduce the problem (or perhaps just part of the problem, or a related problem)!

1. Give yourself access to a Shared Drive through two accounts with different email addresses, which I'll call email addresses A and B.

2. In FFS, connect to the Shared Drive using email address A and perform an initial sync.

3. Upload any new file to the Shared Drive through a web browser using email address B.

4. Repeat the sync in FFS (still connected with email address A). The uploaded file will fail to appear indefinitely.

After doing this and waiting more than 2 hours, my test file still had not appeared, despite the fact that it appeared in the changes list immediately. Double clicking on the file in Google Drive in a web browser while logged in with email address B (the one that uploaded the file) made no difference, but doing that while logged in with email address A (the one connected to FFS) resolved the problem, causing the file to finally appear in a comparison. If the file is uploaded through a web browser by email address A instead, it will immediately appear in FFS.

My interpretation is that until email address A has touched the new file in some way, it is not seen by FFS. Perhaps FFS is querying the changes list and filtering out changes made by others?

I don't think this can fully explain my situation:

My files that are currently not recognized as existing on the Shared Drive were previously acknowledged by FFS, weeks ago. In fact, they were likely originally put there by me using FFS. Now suppose that one of the other individuals with access to the Shared Drive replaced the original version of the file with an updated version through their web browser. How this is done may result in the file ID changing: uploading via drag-and-drop in the browser should preserve the file ID since it is stored as a new version, whereas deleting the original before uploading will generate a new file ID.

In all my testing, if the contents of a file previously recognized by FFS are changed (new version uploaded) by a different user account (different from the one that FFS is connected to), FFS will have no trouble seeing the change. In contrast, if the file is deleted and then replaced by the different user, FFS will think the file was deleted entirely and never acknowledging the replacement. Indeed, the original file ID was deleted, and FFS apparently cannot see the new file created by the other user with the new file ID.

The reason I think this doesn't fully explain my situation is because my files were not declared as deleted at any point that I can remember; instead FFS simply thinks it needs to copy them to the Shared Drive, as if it forgot that it had previously done so. Perhaps there is another wrinkle to my situation that caused this pecularity.

t0ma5, you said you are the only one with access to your Shared Drives, but that they are managed by different organizations. Do you sometimes access them using email addresses that differ from whatever email you've connected FFS to? You also said you only use FFS to interact with them, so perhaps none of this applies to you...

A fair point! I was lazy and cropped out the private information, rather than blurring it. Here is another version showing that the local and remote sources were on the left and right, respectively, and that the comparison mode was two-way.

Thanks for clarifying! The fact that you're using "two-way" which creates a different DB file (sync.ffs_db) doesn't matter here, because this DB is only relevant for determining the sync directions, *not* current existence of files/folders.

I very frequently toggle the comparison mode back and force between "Update" (my default, so that I don't lose data when backing up local files to Google Drive) and "Two-way" (so that I can update local files after a collaborator has put a new version on the Shared Drive). Would this create different database files? Could a situation arise where one database knows about a file on Google Drive, but the other doesn't, leading to different behavior?

An excellent experiment. Here is the entirety of what I got after double-clicking on the animal 15 file:

I'm wondering if FFS is also at "newStartPageToken": "13230". I believe it is, but I'll have to see the contents of the Google Drive .db file just to make sure.

I am willing to share my .db file if that will help, though I'd prefer a less public channel since I'm not sure what can be extracted from it (e.g., login tokens).

So question is why then did the changes list you provided in viewtopic.php?t=7827&start=30#p29606 not lead FFS to conclude existence?

I just noted a peculiarity: The order of change notifications for the first example (it was a great idea you included changes(time)!) and the large time gap between them which implies they were caused by separate actions:

2021-05-06T16:15:11.188Z <shared drive>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv
2021-05-06T19:59:07.974Z <shared drive>/Data/Animal-10_35g_2021-01-18
2021-05-06T23:48:25.655Z <shared drive>/Data
2021-05-06T23:48:25.655Z <shared drive>


There's no way that FFS would conclude "Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" missing at 2021-05-06T16:15:11.188Z.

But what if the real list of changes looked like:

2021-05-06T16:15:11.188Z <shared drive>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv

2021-05-06T19:59:07.000Z REMOVED <shared drive>/Data/Animal-10_35g_2021-01-18

2021-05-06T19:59:07.974Z <shared drive>/Data/Animal-10_35g_2021-01-18
2021-05-06T23:48:25.655Z <shared drive>/Data
2021-05-06T23:48:25.655Z <shared drive>


...where REMOVED could also be some temporary loss of access!? You're on a Shared Drive after all.

Firstly, as manager of the Shared Drive, I have greater privileges than my colleagues who are occasionally changing these files. I don't think they can remove my access temporarily to any part of the drive, but I suppose all sorts of transient server shenanigans are possible.

Secondly, for this particular sequence of timestamps, I think something like that is unlikely. The suspicious timestamp, 2021-05-06T16:15:11.188Z, occurred before I embarked on this forum adventure last Thursday, but the later timestamps that same day probably correspond to tests I was doing for this conversation. At no point did I delete those folders. I have noticed that simply navigating to any folder, or to the root of the Shared Drive, will create a change list entry for that node. I think the folder "changes" you have quoted above are just me visiting the folders in my web browser.

In this case Google would automatically condense the two change notifications

2021-05-06T19:59:07.000Z REMOVED <shared drive>/Data/Animal-10_35g_2021-01-18
2021-05-06T19:59:07.974Z <shared drive>/Data/Animal-10_35g_2021-01-18


into a single one representing the latest state

2021-05-06T19:59:07.974Z <shared drive>/Data/Animal-10_35g_2021-01-18


Are you saying that Google sometimes rewrites the change list history? My naive assumption was that the page token is a reliable index into an unchanging change list. Then again... I'm seeing now that for the two files I've intentionally "fixed" by double-clicking on them (animals 13 and 15), their change list entries with the suspicious timestamp are gone when I re-query with the old page token, and different entries exist with more recent timestamps. The other entires with the suspicious timestamp remain.

How would FFS react to this if a comparison is run right after "2021-05-06T19:59:07.000Z REMOVED"? It would remove the item "<shared drive>/Data/Animal-10_35g_2021-01-18".
But also do one more thing: it would remove the parent folder association for the "<shared drive>/Data/Animal-10_35g_2021-01-18/Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" item, not waiting for the expected change notifications of "Animal-10_35g_2021-01-18 001 EPOCH-ENCODER.csv" that would report a removed parent folder. This second and usually expected change notification does not occur in this example, because the folder is not permanently deleted. Therefore FFS's reaction would be a bug.

If this is what has happened, it would explain all the symptoms! I find it plausible that Google Drive could have temporarily reported a folder deletion/access loss just to have it restored shortly after *without* also sending a change notification for each of its this folder's child elements that the parent folder was removed. I've seen similar behavior with Google Drive's change notifications before. This could be considered a logic bug on Google's side. But anyway, FFS should be robust enough to handle this kind of inconsistency.

Do "run right after" and "restored shortly after" imply that the comparison would need to be run within a narrow window of time, after the access-lost notification is issued but before it is removed again via condensation with another notification? This seems unlikely to happen by chance, especially when I normally run this sync at most a few times per week, and not hundreds of times per day.

To verify this theory, I'll have to have a look at the content of your Google Drive .db file. I hope you haven't done any changes to your Google Drive, so that it is in a state that matches your screenshot download/file.php?id=1911&sid=747fdbe97e53646a93e785f2da98d13f

A few things have changed due to the tests I've been running (e.g., animal 15 dropped off the list) and because new data files have been added for a new animal by a collaborator which I have avoided syncing yet, but it's mostly the same. When I share my .db file, I'll make sure you have a concurrent snapshot. Just let me know how I can share it privately.

Instead of explicitly specifying the fields you want, I believe you can also set "*" to get all the data available in the change notifications.

Yes, using "*" did expose a lot more data, including "viewedByMeTime" and "lastModifyingUser", but I'm not sure that I've learned anything from it. I'm frustrated that there isn't a field that clearly indicates what triggered the entry! Since lastModifyingUser includes the names and email addresses of some of my collaborators, I'm hesitant to publish the full version here, but would be willing to share it privately along with the .db file.

I regularly use FFS with WinMerge to help me monitor and track unannounced changes (though in this case FFS has blind spots for duplicated files).

The internal model of FFS closely follows that of Google Drive, so these duplicate file names are accounted for. But this concept obviously doesn't fit with normal file system rules that FFS represents on its GUI, so it shows only a single line item. But were you to interact with such a line item in any way, FFS would issue errors about the underlying ambiguity of the file path.

Ah, yes, I have seen that before. Thanks for the clarification.

Still, suppose FFS has struck files from its database. Why then does FFS seem to ignore the recent entries with the suspicious timestamps, which imply the files exist but don't indicate they were trashed?

I believe the items are still existing in FFS's Google Drive .db files, just the association with their parent folder is severed, thous they're shown as not existing "at this path", but orphaned items (in FFS's view).

OK, I hope that inspection of my .db file might be able to determine if you are right!

If this is what has happened, it would explain all the symptoms! I find it plausible that Google Drive could have temporarily reported a folder deletion/access loss just to have it restored shortly after *without* also sending a change notification for each of its this folder's child elements that the parent folder was removed. I've seen similar behavior with Google Drive's change notifications before. This could be considered a logic bug on Google's side.

I might be wrong here. Losing access to a folder but NOT to its contained files actually may be something that the Google Drive model simply allows (unlike normal file systems). Sure, the child items will be orphaned, but they should not be considered deleted.
Technically, FFS correctly considers them orphaned, too, it's just that Google won't send any change notifications for the child items again when parent folder access is restored. Additionally, orphaned items aren't persisted in the .db file by FFS.

Haha, OK, so maybe inspection of the .db file will not be so helpful? Still happy to share.

Boy, these posts are long, haha.

[jpgill86]

I just noticed that my Shared Drive's "Data" folder (the root for the sync) contains two sync.ffs_db files. o_O One was last modified a few minutes ago, and the other was last modified April 26.

two-sync-ffs-db.PNG (4.73 KiB) Viewed 47787 times

[Zenju]

I think I've found a way to reliably reproduce the problem (or perhaps just part of the problem, or a related problem)!

1. Give yourself access to a Shared Drive through two accounts with different email addresses, which I'll call email addresses A and B.

2. In FFS, connect to the Shared Drive using email address A and perform an initial sync.

3. Upload any new file to the Shared Drive through a web browser using email address B.

4. Repeat the sync in FFS (still connected with email address A). The uploaded file will fail to appear indefinitely.

Wow, I can reproduce this!
It's the standard Shared Drive scenario not working!

After doing this and waiting more than 2 hours, my test file still had not appeared, despite the fact that it appeared in the changes list immediately. Double clicking on the file in Google Drive in a web browser while logged in with email address B (the one that uploaded the file) made no difference, but doing that while logged in with email address A (the one connected to FFS) resolved the problem, causing the file to finally appear in a comparison. If the file is uploaded through a web browser by email address A instead, it will immediately appear in FFS.

Problem is, FFS isn't receiving any change notifications from Google. Only after you access an item as you described, change notifications are received by FFS.


How can this be when FFS sets includeItemsFromAllDrives?
https://developers.google.com/drive/api/v3/reference/changes/list

I've read Google was planning to deprecate this parameter middle of last year, but then didn't. In any case, the behavior is not what one would think it is. "includeItemsFromAllDrives" definitively does NOT include items from all drives. Unfortunately this is what FFS was expecting.

https://developers.google.com/drive/api/v3/enable-shareddrives

includeItemsFromAllDrives     driveId     Query Description
true     No     Changes are reflective of changes to files inside or outside of shared drives that the user has accessed, as well as changes to shared drives in which the user is a member.
true     Yes     Changes are reflective of changes to the particular shared drive that was specified and items inside that shared drive.


FFS doesn't set the drive id, so we have

Changes are reflective of changes to files inside or outside of shared drives that the user has accessed,
as well as changes to shared drives in which the user is a member.

Playing language lawyer, this is exactly the behavior we've seen. One would assume that "changes to shared drives" would include also changes to files in shared drives, but this is not what is happening in practice, and if it were, the first part of the sentence would be redundant.

So... everything works as described by Google. Except, the variable name "includeItemsFromAllDrives" is a blatant lie (but surely was not when I implemented Shared Drives in FFS more than a year ago).

I don't think this can fully explain my situation:

I agree, for the files to be seen as deleted, there must have been a corresponding change notification at some time. An update doesn't generate such a notification, only a proper delete + a new upload, assuming the notification for the upload is somehow not received by FFS.

I very frequently toggle the comparison mode back and force between "Update" (my default, so that I don't lose data when backing up local files to Google Drive) and "Two-way" (so that I can update local files after a collaborator has put a new version on the Shared Drive). Would this create different database files? Could a situation arise where one database knows about a file on Google Drive, but the other doesn't, leading to different behavior?

Doesn't matter. Sync.ffs_db file have no say on whether a file exists on Google Drive or not.

Are you saying that Google sometimes rewrites the change list history? My naive assumption was that the page token is a reliable index into an unchanging change list.

Google condenses change notifications. You won't find more than one change notification per item.

To verify this theory, I'll have to have a look at the content of your Google Drive .db file. I hope you haven't done any changes to your Google Drive, so that it is in a state that matches your screenshot download/file.php?id=1911&sid=747fdbe97e53646a93e785f2da98d13f

After more thinking: Theory is moot. Even if Google Drive would emit a change notification for a deleted folder, without notifying child items, FFS will behave correctly, because FolderContent::isKnownFolder will be false. So the next access, should this folder reappear, will trigger a rescan. The FFS implementation in this regard is actually pretty much ideal, because it also covers the case of the folder *not* reappering without accumulating orphaned file items needlessly.


So all in all, there is one big TODO for FFS: Fix receiving change notifications for Shared Drives.

[jpgill86]

Wow, I can reproduce this!

Progress!

FFS doesn't set the drive id

In all my testing, I always set driveId, thinking it was necessary. However, I see in FFS's getChangesDelta that driveId is not included among the query parameters. Looks like this parameter makes all the difference. If it's not included, the file uploaded by a different email account will not appear in the changes list; if it is included, it will be. Could FFS start using driveId in getChangesDelta? Note that getStartPageToken returns a very different token depending on whether or not driveId is provided.

I've read Google was planning to deprecate this parameter middle of last year, but then didn't.

I see that there is a deprecated alias, includeTeamDriveItems. Are you perhaps thinking of that?

Playing language lawyer, this is exactly the behavior we've seen. One would assume that "changes to shared drives" would include also changes to files in shared drives, but this is not what is happening in practice, and if it were, the first part of the sentence would be redundant.

So... everything works as described by Google. Except, the variable name "includeItemsFromAllDrives" is a blatant lie

I completely agree with your assessment, haha!

[jpgill86]

After more thinking: Theory is moot.

I want this on a t-shirt.

[Zenju]

I see that there is a deprecated alias, includeTeamDriveItems. Are you perhaps thinking of that?

No, it was "includeItemsFromAllDrives",
https://developers.google.com/resources/api-libraries/documentation/drive/v3/python/latest/drive_v3.changes.html

includeItemsFromAllDrives: boolean, Deprecated - Whether both My Drive and shared drive items should be included in results. This parameter will only be effective until June 1, 2020. Afterwards shared drive items are included in the results.


Looks like this parameter makes all the difference. If it's not included, the file uploaded by a different email account will not appear in the changes list; if it is included, it will be. Could FFS start using driveId in getChangesDelta? Note that getStartPageToken returns a very different token depending on whether or not driveId is provided.

Apparently, that's the fix. Interestingly, if a drive ID is set, and includeItemsFromAllDrives is set to false, the list call fails. On the other hand if set to yes, list still does not return changes from *all* drives, but only for the selected one (as is documented). In other words, the API design is skewed: If drive ID is set, the "includeItemsFromAllDrives" parameter is practically meaningless, but needlessly required to be set to "true".
If no drive ID is set, "includeItemsFromAllDrives" configures whether added/deleted or renamed drives are notified. The added "bonus" of getting notifications of the subset of shared drive files that were accessed is of no value for FFS.

So to sum up: drive notifications are per drive, but "my drive" is special, because it also get's notifications about added/removed drives. Doesn't look like an easy fix.

[jpgill86]

So to sum up: drive notifications are per drive, but "my drive" is special, because it also get's notifications about added/removed drives. Doesn't look like an easy fix.

Are you saying it's more complicated than just adding driveId to the queries?

I know these things can be hard to estimate, but would you guess a fix for FFS is a week away, a month away, a year away, ...?

I think at this point my system's state is no longer of much value to preserve for the purpose of debugging. I'd like to execute the workaround (disconnect Google Drive authorization, then reconnect to rescan the drive), if you agree.

[Zenju]

Are you saying it's more complicated than just adding driveId to the queries?

A lot more. The Gdrive code needs some medium refactoring. Goal is to have this fixed for the next FFS release.

I think at this point my system's state is no longer of much value to preserve for the purpose of debugging. I'd like to execute the workaround (disconnect Google Drive authorization, then reconnect to rescan the drive), if you agree.

Yes that'll be fine.

[Zenju]

Fixed. File notification handling is now per drive:
https://www.mediafire.com/file/eyyx8uvecp96pxg/FreeFileSync_11.11_%255BBeta%255D_Windows_Setup.exe

[jpgill86]

Fixed. File notification handling is now per drive:
https://www.mediafire.com/file/eyyx8uvecp96pxg/FreeFileSync_11.11_%255BBeta%255D_Windows_Setup.exe

This appears to work perfectly! I tried the reproducible test previously described, and some variants I thought of. I'll plan to keep using this beta version until 11.11 is officially released, and let you know if I encounter any problems.

Thanks so much Zenju for being so responsive and efficient! 😍 I'll make sure my next donation is a little bigger!

[t0ma5]

Fixed. File notification handling is now per drive:
https://www.mediafire.com/file/eyyx8uvecp96pxg/FreeFileSync_11.11_%255BBeta%255D_Windows_Setup.exe

Thank you very much for the time and effort to solve this issue. Thanks also jpgill86 for contributing to finding the root of the problem! You guys made my day!

[jpgill86]

Thank you very much for the time and effort to solve this issue. Thanks also jpgill86 for contributing to finding the root of the problem! You guys made my day!

Hi t0ma5! I'm wondering if you had thoughts on this:

t0ma5, you said you are the only one with access to your Shared Drives, but that they are managed by different organizations. Do you sometimes access them using email addresses that differ from whatever email you've connected FFS to? You also said you only use FFS to interact with them, so perhaps none of this applies to you...

I hope Zenju's fix applies to you too!

[t0ma5]

Hi t0ma5! I'm wondering if you had thoughts on this:

t0ma5, you said you are the only one with access to your Shared Drives, but that they are managed by different organizations. Do you sometimes access them using email addresses that differ from whatever email you've connected FFS to? You also said you only use FFS to interact with them, so perhaps none of this applies to you...

I hope Zenju's fix applies to you too!

I upload files and folders via web browser to 1 of my SHARED DRIVES and then I sync them (1 way mirror) with others via FFS. So it's always DRIVE 1 TO DRIVE 2, DRIVE 1 TO DRIVE 3, DRIVE 1 TO DRIVE 4, and so on. Nobody else modifieds the files in those drives except for me.

[jpgill86]

🎉 Eleven eleven, released this day, hooray hooray! 🎊