[SOLVED] Files Disappearing from GCrypt Mount

Brief Summary of Issue: Files disappear from gcrypt mount but become visible after unmounting and remounting

rclone version:

rclone v1.50.0
- os/arch: linux/amd64
- go version: go1.13.3

Cloud Storage Used
GSuite personal drive with an rclone crypt inside.

System Information

System:  Kernel: 5.3.7-arch1-1-ARCH x86_64 bits: 64 compiler: gcc v: 9.2.0 Console: tty 4 
         Distro: Arch Linux 

In Depth Description of Issue
During the past month, files have started disappearing somewhat randomly from my GCrypt mount at a rate of roughly 10 out of 20000 per day. About 9 of those are uploaded on the same day as they disappear, while the remaining 1 is completely random. Running ls -a with both regular and superuser accounts confirms that the files are no longer present in the mount. Restarting the GCrypt mount shows the files again.

Additionally, I would like to note that I had this issue beginning about a month ago, so this is not specific to rclone v1.50.0. I am also running a MergerFS mount if that is relevant (however, note that I made sure to check the files in the original GCrypt mount point).

Systemd file for GCrypt Mount

[Unit]
Description=RClone Service
Wants=network-online.target
After=network-online.target

[Service]
Type=notify
Environment=RCLONE_CONFIG=/home/aVid/.config/rclone/rclone.conf
KillMode=none
RestartSec=5
ExecStart=rclone mount gcrypt: /mnt/Media \
--allow-other \
--attr-timeout 1000h \
--buffer-size 1G \
--dir-cache-time 1000h \
--log-level INFO \
--log-file /home/aVid/.config/rclone/rclone.log \
--poll-interval 15s \
--timeout 1h \
--umask 002 \
--user-agent aViDagent
ExecStop=/bin/fusermount -uz /mnt/Media
Restart=on-failure
User=aVid

[Install]
WantedBy=multi-user.target

Selective RClone Log File
I see the following errors appear about once every five minutes. I initially ran with DEBUG level logging and searched for files that had disappeared, but saw no errors associated with them.

Google drive root 'GCryptCenter': Failed to get StartPageToken: Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&prettyPrint=false&supportsAllDrives=true: stream error: stream ID 2141; INTERNAL_ERROR

Google drive root 'GCryptCenter': Change notify listener failure: Get https://www.googleapis.com/drive/v3/changes?alt=json&fields=nextPageToken%2CnewStartPageToken%2Cchanges%28fileId%2Cfile%28name%2Cparents%2CmimeType%29%29&includeItemsFromAllDrives=true&pageSize=1000&pageToken={Removed}&prettyPrint=false&supportsAllDrives=true: stream error: stream ID 623; INTERNAL_ERROR

This sounds like a known issue we worked on during 1.49.4 and 1.49.5

The problem here is that your changes-on-drive polling is failing and thus the VFS cache is not being updated correctly. You could confirm this by turning on the remote control
--rc
and sending one of these commands

rclone rc vfs/forget

or

rclone rc vfs/refresh

to either purge or refresh the VFS cache (while running). Either should result in new listings and making those files re-appear. Restarting the mount is effectively the same as a VFS purge, so that explains why that would temporarily fix the issue.

But that's not the underlying problem I think. It's those "INTERNAL ERROR" errors.
I thought/hoped we had gotten rid of this.

@ncw will probably want to be aware of this (he should come along soon tomorrow I bet).
But long story short I suspect this is an rclone problem that will need to be fixed - and not due to user-error. Either that or it is actually possible this is some temporary issue on Google's side. We are aware of some recent issues and suspect they may be restructuring parts of the system (but this is just speculation). We aren't 100% sure on the root cause yet and the fix implemented in 1.50 for this issue was more of a speculative one...

Unless by chance you happen to use this in your Gdrive remote config:
disable_http2 = false
(because this would disable the speculative fix)
but this is not something you would enable by accident exactly...

I have added the --rc option to my mount options and will report if your commands are successful tomorrow (this gives some time for files to disappear).

I do not use the option "disable_http2=false" in my Gdrive remote config.

You are definitely seeing these INTERNAL_ERROR messages with rclone 1.50.0? Can you double check? If you use rclone rc core/version it will show you the version of the running rclone.

And if you do this

rclone about gcrypt: -vv --dump headers 2>&1 | grep HTTP/

What does it print?

Running rclone rc core/version gives

{
	"arch": "amd64",
	"decomposed": [
		1,
		50,
		0
	],
	"goVersion": "go1.13.3",
	"isGit": false,
	"os": "linux",
	"version": "v1.50.0"
}

Running rclone about gcrypt: -vv --dump headers 2>&1 | grep HTTP/ gives

2019/10/30 07:56:05 DEBUG : GET /drive/v3/files?alt=json&fields=files%28id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%29%2CnextPageToken&includeItemsFromAllDrives=true&pageSize=1000&prettyPrint=false&q=trashed%3Dfalse+and+%28%{Redacted}%27+in+parents%29+and+%28name%3D%27Media%27%29+and+mimeType%3D%27application%2Fvnd.google-apps.folder%27&supportsAllDrives=true HTTP/1.1
2019/10/30 07:56:06 DEBUG : HTTP/1.1 200 OK
2019/10/30 07:56:06 DEBUG : GET /drive/v3/about?alt=json&fields=exportFormats%2CimportFormats&prettyPrint=false HTTP/1.1
2019/10/30 07:56:06 DEBUG : HTTP/1.1 200 OK
2019/10/30 07:56:06 DEBUG : GET /drive/v3/files?alt=json&fields=files%28id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%29%2CnextPageToken&includeItemsFromAllDrives=true&pageSize=1000&prettyPrint=false&q=trashed%3Dfalse+and+%28%{Redacted}%27+in+parents%29+and+%28name%3D%27Media%27%29+and+mimeType%3D%27application%2Fvnd.google-apps.folder%27&supportsAllDrives=true HTTP/1.1
2019/10/30 07:56:06 DEBUG : HTTP/1.1 200 OK
2019/10/30 07:56:06 DEBUG : GET /drive/v3/about?alt=json&fields=storageQuota&prettyPrint=false HTTP/1.1
2019/10/30 07:56:06 DEBUG : HTTP/1.1 200 OK

However, the rclone mount has not lost any files today and I do not see any INTERNAL_ERROR messages as of late. I may have forgotten to restart the rclone mount after updating to rclone 1.50.0. I'll report if I see more INTERNAL_ERROR messages. For now, I will mark the issue as solved.

Doubtful you could replace the executable WHILE it was running... that would be quite a feat :slight_smile:

Ah good! Your grep HTTP was as expected - all the HTTP are HTTP/1.1 not HTTP/2

I was worried that somehow this fix had fallen out of 1.50...