In some cases, GDriveFS tries to open already deleted temp files

[frankiestallone]

I've been toying with using CryFS in conjunction with GDriveFS. It works fairly well, except CryFS semi-frequently triggers what I think is a bug in GDriveFS. From the terminal, the symptoms were just an "Input/Output Error" when doing random operations (making a directory, removing a directory, ls, etc.)

Running GDriveFS in debug mode reveals what appears to be happening:

unique: 557, opcode: RELEASE (18), nodeid: 10, insize: 64, pid: 0
release[23] flags: 0x8001
2016-09-27 03:08:47,244 [gdrivefs.gdfs.fsutility DEBUG] --------------------------------------------------
2016-09-27 03:08:47,244 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> release(10) >>>>>>>>>> (0)
2016-09-27 03:08:47,245 [gdrivefs.gdfs.fsutility DEBUG] DATA: fh= [23]  filepath= [/TestE/315/8262D33FB59841429B884B28AAD17]
2016-09-27 03:08:47,245 [gdrivefs.gdfs.opened_file DEBUG] Closing opened-file with handle (23).
2016-09-27 03:08:47,245 [gdrivefs.gdfs.opened_file DEBUG] Removing temporary file [/tmp/tmpB9hxpW/22] ([/TestE/315/8262D33FB59841429B884B28AAD17]).
2016-09-27 03:08:47,245 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< release(10) (0)
   unique: 557, success, outsize: 16
unique: 558, opcode: GETATTR (3), nodeid: 6, insize: 56, pid: 690
getattr /TestE/25E/1C8072E1AC47323E15CF359429CE1
2016-09-27 03:08:47,245 [gdrivefs.gdfs.fsutility DEBUG] --------------------------------------------------
2016-09-27 03:08:47,245 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> getattr(4) >>>>>>>>>> (690)
2016-09-27 03:08:47,245 [gdrivefs.gdfs.fsutility DEBUG] DATA: fh= [None]  raw_path= [/TestE/25E/1C8072E1AC47323E15CF359429CE1]
2016-09-27 03:08:47,246 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< getattr(4) (690)
   unique: 558, success, outsize: 120
unique: 559, opcode: READ (15), nodeid: 6, insize: 80, pid: 690
read[24] 32768 bytes from 16384 flags: 0x8000
2016-09-27 03:08:47,246 [gdrivefs.gdfs.fsutility DEBUG] --------------------------------------------------
2016-09-27 03:08:47,246 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> read(6) >>>>>>>>>> (690)
2016-09-27 03:08:47,247 [gdrivefs.gdfs.fsutility DEBUG] DATA: fh= [24]  length= [32768]  raw_path= [/TestE/25E/1C8072E1AC47323E15CF359429CE1]  offset= [16384]
2016-09-27 03:08:47,247 [gdrivefs.gdfs.fsutility DEBUG] OF: >>>>>>>>>> read(3) >>>>>>>>>> (690)
2016-09-27 03:08:47,247 [gdrivefs.gdfs.fsutility DEBUG] DATA: length= [32768]  offset= [16384]
2016-09-27 03:08:47,247 [gdrivefs.gdfs.opened_file DEBUG] Reading (32768) bytes at offset (16384).
2016-09-27 03:08:47,247 [gdrivefs.gdfs.fsutility ERROR] There was an exception in [read]
Traceback (most recent call last):
  File "/usr2/pub2/home/gdrive/.local/lib/python2.7/site-packages/gdrivefs/gdfs/fsutility.py", line 71, in wrapper
    result = f(*args, **kwargs)
  File "/usr2/pub2/home/gdrive/.local/lib/python2.7/site-packages/gdrivefs/gdfs/opened_file.py", line 392, in read
    st = os.stat(self.__temp_filepath)
OSError: [Errno 2] No such file or directory: '/tmp/tmpB9hxpW/22'
2016-09-27 03:08:47,248 [gdrivefs.gdfs.fsutility DEBUG] OF: <<<<<<<<<< read(3) (690) (E(OSError): "[Errno 2] No such file or directory: '/tmp/tmpB9hxpW/22'")
2016-09-27 03:08:47,248 [gdrivefs.gdfs.gdfuse ERROR] Could not read data.
Traceback (most recent call last):
  File "/usr2/pub2/home/gdrive/.local/lib/python2.7/site-packages/gdrivefs/gdfs/gdfuse.py", line 232, in read
    return opened_file.read(offset, length)
  File "/usr2/pub2/home/gdrive/.local/lib/python2.7/site-packages/gdrivefs/gdfs/fsutility.py", line 71, in wrapper
    result = f(*args, **kwargs)
  File "/usr2/pub2/home/gdrive/.local/lib/python2.7/site-packages/gdrivefs/gdfs/opened_file.py", line 392, in read
    st = os.stat(self.__temp_filepath)
OSError: [Errno 2] No such file or directory: '/tmp/tmpB9hxpW/22'
2016-09-27 03:08:47,248 [gdrivefs.gdfs.fsutility ERROR] FUSE error [FuseOSError] (5) will be forwarded back to GDFS from [read]: [Errno 5] Input/output error
2016-09-27 03:08:47,249 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< read(6) (690)
   unique: 559, error: -5 (Input/output error), outsize: 16

The temporary file /tmp/tmpB9hxpW/22 was deleted, and then shortly after an attempt was made to open it.

What I'm not clear on is why it was deleted. It seems to be deleted when /TestE/315/8262D33FB59841429B884B28AAD17 is released, but then the same temporary file is opened when trying to read /TestE/25E/1C8072E1AC47323E15CF359429CE1.

I just started toying with this (installed via pip today), so I don't know if this is a recent issue or not. If anyone else wants to reproduce, it my experience it's pretty easy to reproduce by just mkdir and rmdir a few directories a few times in a CryFS mounted inside of a GDriveFS.