GDriveFS icon indicating copy to clipboard operation
GDriveFS copied to clipboard
verified publisher icon dsoprea

ls: Input/output error

Open zyxmon opened this issue 9 years ago • 10 comments

I have build GDriveFS for Entware - https://github.com/Entware-ng/Entware-ng (I have used pip install for testing). fuse mount seems to work gdfs(/opt/var/cache/gdfs.creds) on /opt/gdrive type fuse (rw,nosuid,nodev,relatime,user_id=0,group_id=0) When I try to access mounted folder I have Input/output error. Here is a debug log

>GD_DEBUG=1 gdfs /opt/var/cache/gdfs.creds /opt/gdrive
2016-07-06 06:42:14,275 [gdrivefs.utility INFO] No extension-mapping was found.
2016-07-06 06:42:14,611 [__main__ DEBUG] Mounting GD with creds at [/opt/var/cache/gdfs.creds]: /opt/gdrive
2016-07-06 06:42:14,615 [gdrivefs.gdfs.gdfuse DEBUG] FUSE options:
{}
2016-07-06 06:42:14,619 [gdrivefs.gdfs.gdfuse DEBUG] PERMS: F=777 E=666 NE=444
2016-07-06 06:42:14,673 [gdrivefs.gdtool.oauth_authorize INFO] Credentials have expired. Attempting to refresh them.
2016-07-06 06:42:14,675 [gdrivefs.gdtool.oauth_authorize INFO] Doing credentials refresh.
2016-07-06 06:42:14,679 [oauth2client.client INFO] Refreshing access_token
2016-07-06 06:42:15,282 [gdrivefs.gdtool.drive DEBUG] Getting authorized HTTP tunnel.
2016-07-06 06:42:15,287 [gdrivefs.gdtool.drive DEBUG] Got authorized tunnel.
FUSE library version: 2.9.3
nullpath_ok: 0
nopath: 0
utime_omit_ok: 0
unique: 1, opcode: INIT (26), nodeid: 0, insize: 56, pid: 0
INIT: 7.18
flags=0x0000047b
max_readahead=0x00020000
2016-07-06 06:42:16,522 [gdrivefs.gdfs.fsutility DEBUG] --------------------------------------------------
2016-07-06 06:42:16,524 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> init(23) >>>>>>>>>> (0)
2016-07-06 06:42:16,528 [gdrivefs.gdfs.fsutility DEBUG] DATA: path= [/]
2016-07-06 06:42:16,530 [gdrivefs.gdfs.gdfuse INFO] Activating change-monitor.
2016-07-06 06:42:16,876 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< init(23) (0)
2016-07-06 06:42:16,879 [gdrivefs.gdtool.drive DEBUG] Getting authorized HTTP tunnel.
2016-07-06 06:42:16,883 [gdrivefs.gdtool.drive DEBUG] Got authorized tunnel.
   INIT: 7.19
   flags=0x00000011
   max_readahead=0x00020000
   max_write=0x00020000
   max_background=0
   congestion_threshold=0
   unique: 1, success, outsize: 40
unique: 2, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 10738
getattr /
2016-07-06 06:42:43,640 [gdrivefs.gdfs.fsutility DEBUG] --------------------------------------------------
2016-07-06 06:42:43,642 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> getattr(4) >>>>>>>>>> (10738)
2016-07-06 06:42:43,644 [gdrivefs.gdfs.fsutility DEBUG] DATA: fh= [None]  raw_path= [/]
2016-07-06 06:42:43,659 [gdrivefs.cache.cacheclient_base DEBUG] CacheClientBase(CacheClientBase,28800)
2016-07-06 06:42:43,662 [gdrivefs.cache.cache_agent INFO] Starting cache-cleanup thread: <gdrivefs.cache.cache_agent.CacheAgent object at 0xf65858>
2016-07-06 06:42:43,670 [gdrivefs.cache.cache_agent INFO] Cache-cleanup thread running: <gdrivefs.cache.cache_agent.CacheAgent object at 0xf65858>
2016-07-06 06:42:43,669 [gdrivefs.gdtool.drive INFO] Getting client for parent-listing.
2016-07-06 06:42:43,675 [gdrivefs.gdtool.drive INFO] Listing entries over child with ID [0AP09GPqvAIMZUk9PVA].
2016-07-06 06:42:44,902 [gdrivefs.gdtool.drive DEBUG] (1) entries were retrieved.
2016-07-06 06:42:44,908 [gdrivefs.cache.volume DEBUG] Recursively pruning entry with ID [0AP09GPqvAIMZUk9PVA].
2016-07-06 06:42:44,928 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< getattr(4) (10738)
   unique: 2, success, outsize: 120

I am running it on a mipsel device where part of the filesystem is read only. May be it is cache issue?

BTW I have no problems running davfs2, encfs on this router.

zyxmon avatar Jul 06 '16 03:07 zyxmon

I'm not familiar with mipsel. Which part of the filesystem is readonly? Writes will only be performed on the tmpfs mount, whereever that happens to be.

If you get an error during access, there will be an error in the log. Almost all of the slice that you provided is the standard stuff following a mount. There has to be more.

On Tue, Jul 5, 2016 at 11:59 PM, zyxmon [email protected] wrote:

I have build GDriveFS for Entware - https://github.com/Entware-ng/Entware-ng (I have used pip install for testing). fuse mount seems to work gdfs(/opt/var/cache/gdfs.creds) on /opt/gdrive type fuse (rw,nosuid,nodev,relatime,user_id=0,group_id=0) When I try to access mounted folder I have Input/output error. Here is a debug log

GD_DEBUG=1 gdfs /opt/var/cache/gdfs.creds /opt/gdrive 2016-07-06 06:42:14,275 [gdrivefs.utility INFO] No extension-mapping was found. 2016-07-06 06:42:14,611 [main DEBUG] Mounting GD with creds at [/opt/var/cache/gdfs.creds]: /opt/gdrive 2016-07-06 06:42:14,615 [gdrivefs.gdfs.gdfuse DEBUG] FUSE options: {} 2016-07-06 06:42:14,619 [gdrivefs.gdfs.gdfuse DEBUG] PERMS: F=777 E=666 NE=444 2016-07-06 06:42:14,673 [gdrivefs.gdtool.oauth_authorize INFO] Credentials have expired. Attempting to refresh them. 2016-07-06 06:42:14,675 [gdrivefs.gdtool.oauth_authorize INFO] Doing credentials refresh. 2016-07-06 06:42:14,679 [oauth2client.client INFO] Refreshing access_token 2016-07-06 06:42:15,282 [gdrivefs.gdtool.drive DEBUG] Getting authorized HTTP tunnel. 2016-07-06 06:42:15,287 [gdrivefs.gdtool.drive DEBUG] Got authorized tunnel. FUSE library version: 2.9.3 nullpath_ok: 0 nopath: 0 utime_omit_ok: 0 unique: 1, opcode: INIT (26), nodeid: 0, insize: 56, pid: 0 INIT: 7.18 flags=0x0000047b max_readahead=0x00020000 2016-07-06 06:42:16,522 [gdrivefs.gdfs.fsutility DEBUG] -------------------------------------------------- 2016-07-06 06:42:16,524 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> init(23) >>>>>>>>>> (0) 2016-07-06 06:42:16,528 [gdrivefs.gdfs.fsutility DEBUG] DATA: path= [/] 2016-07-06 06:42:16,530 [gdrivefs.gdfs.gdfuse INFO] Activating change-monitor. 2016-07-06 06:42:16,876 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< init(23) (0) 2016-07-06 06:42:16,879 [gdrivefs.gdtool.drive DEBUG] Getting authorized HTTP tunnel. 2016-07-06 06:42:16,883 [gdrivefs.gdtool.drive DEBUG] Got authorized tunnel. INIT: 7.19 flags=0x00000011 max_readahead=0x00020000 max_write=0x00020000 max_background=0 congestion_threshold=0 unique: 1, success, outsize: 40 unique: 2, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 10738 getattr / 2016-07-06 06:42:43,640 [gdrivefs.gdfs.fsutility DEBUG] -------------------------------------------------- 2016-07-06 06:42:43,642 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> getattr(4) >>>>>>>>>> (10738) 2016-07-06 06:42:43,644 [gdrivefs.gdfs.fsutility DEBUG] DATA: fh= [None] raw_path= [/] 2016-07-06 06:42:43,659 [gdrivefs.cache.cacheclient_base DEBUG] CacheClientBase(CacheClientBase,28800) 2016-07-06 06:42:43,662 [gdrivefs.cache.cache_agent INFO] Starting cache-cleanup thread: <gdrivefs.cache.cache_agent.CacheAgent object at 0xf65858> 2016-07-06 06:42:43,670 [gdrivefs.cache.cache_agent INFO] Cache-cleanup thread running: <gdrivefs.cache.cache_agent.CacheAgent object at 0xf65858> 2016-07-06 06:42:43,669 [gdrivefs.gdtool.drive INFO] Getting client for parent-listing. 2016-07-06 06:42:43,675 [gdrivefs.gdtool.drive INFO] Listing entries over child with ID [0AP09GPqvAIMZUk9PVA]. 2016-07-06 06:42:44,902 gdrivefs.gdtool.drive DEBUG entries were retrieved. 2016-07-06 06:42:44,908 [gdrivefs.cache.volume DEBUG] Recursively pruning entry with ID [0AP09GPqvAIMZUk9PVA]. 2016-07-06 06:42:44,928 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< getattr(4) (10738) unique: 2, success, outsize: 120

I am running it on a mipsel device where part of the filesystem is read only. May be it is cache issue?

BTW I have no problems running davfs2, encfs on this router.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/dsoprea/GDriveFS/issues/161, or mute the thread https://github.com/notifications/unsubscribe/AArralrxvgG3UBM6AhNQ2XF47reM3QNlks5qSygOgaJpZM4JFvCc .

dsoprea avatar Jul 06 '16 04:07 dsoprea

rootfs is RO. /tmp /var are tmpfs /opt is a usb drive where gdrivefs is installed. Nothing more in the log after ls <mountpoint> in another terminal.

zyxmon avatar Jul 06 '16 04:07 zyxmon

Unmount and remount, then. Try the following until something produces an error:

  1. ls from outside the mount (twice).
  2. ls from inside the mount (on ".", twice).
  3. ls a specific member.
  4. From the mountpoint, change into a child directory and do another ls.
  5. Do a copy from outside the mount into the mount.
  6. ls what you copied.
  7. Do a delete of what you copied.
  8. Unmount.

On Wed, Jul 6, 2016 at 12:47 AM, zyxmon [email protected] wrote:

rootfs is RO. /tmp /var are tmpfs /opt is a usb drive where gdrivefs is installed. Nothing more in the log after ls in another terminal.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/dsoprea/GDriveFS/issues/161#issuecomment-230670107, or mute the thread https://github.com/notifications/unsubscribe/AArrajYsdyo0bqD2TPFgF7IFvVYzoi8sks5qSzNOgaJpZM4JFvCc .

dsoprea avatar Jul 06 '16 04:07 dsoprea

After the first Input/Output error mount point is displayed with a question mark a a first char. All operation with it produce Input/Output error and no debug log. I had similar behavior with encfs. Upgrading encfs solved the problem.

zyxmon avatar Jul 06 '16 05:07 zyxmon

You're not aware of the use of any non-English-friendly character sets in file naming are you (not that that'd necessarily cause a problem)?

On Wed, Jul 6, 2016 at 1:09 AM, zyxmon [email protected] wrote:

After the first Input/Output error mount point is displayed with a question mark a a first char. All operation with it produce Input/Output error and no debug log. I had similar behavior with encfs. Upgrading encfs solved the problem.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/dsoprea/GDriveFS/issues/161#issuecomment-230672350, or mute the thread https://github.com/notifications/unsubscribe/AArram24Xibn5QY1Zmmc57cAkCi14wv-ks5qSzh0gaJpZM4JFvCc .

dsoprea avatar Jul 06 '16 05:07 dsoprea

Another two options:

  1. Try it in Vagrant using the included Vagrant file.
  2. Start it in the foreground and in debug mode. Note that you'll likely have to unmount and then SIGHUP it to shut it down. Example:

GD_DEBUG=1 GD_MONITOR_CHANGES=0 gdfs /var/cache/gdfs.creds /mnt/g

Dustin

On Wed, Jul 6, 2016 at 1:12 AM, Dustin Oprea [email protected] wrote:

You're not aware of the use of any non-English-friendly character sets in file naming are you (not that that'd necessarily cause a problem)?

On Wed, Jul 6, 2016 at 1:09 AM, zyxmon [email protected] wrote:

After the first Input/Output error mount point is displayed with a question mark a a first char. All operation with it produce Input/Output error and no debug log. I had similar behavior with encfs. Upgrading encfs solved the problem.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/dsoprea/GDriveFS/issues/161#issuecomment-230672350, or mute the thread https://github.com/notifications/unsubscribe/AArram24Xibn5QY1Zmmc57cAkCi14wv-ks5qSzh0gaJpZM4JFvCc .

dsoprea avatar Jul 06 '16 05:07 dsoprea

All the files and folders are ansi (english). There is no vagrant. I need to build it in Entware. I test gdrivefs on an embeded mipsel router with 128MB of ram and 700Mhz mipsel cpu. Nearly all software on it comes from Entware project (about 1800 packages).

zyxmon avatar Jul 06 '16 05:07 zyxmon

Some more debug output lines

2016-07-06 08:26:33,854 [gdrivefs.gdtool.drive DEBUG] We received (1) changes to apply.
2016-07-06 08:26:33,857 [gdrivefs.gdtool.drive DEBUG] CHANGE: [0B_09GPqvAIMZM1o4a2RLUjd2OGc] [test] (UPDATED)
2016-07-06 08:32:38,893 [gdrivefs.gdfs.fsutility DEBUG] --------------------------------------------------
2016-07-06 08:32:38,904 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> destroy(24) >>>>>>>>>> (0)
2016-07-06 08:32:38,907 [gdrivefs.gdfs.fsutility DEBUG] DATA: path= [/]
2016-07-06 08:32:38,910 [gdrivefs.gdfs.gdfuse INFO] Stopping change-monitor.
2016-07-06 08:32:42,290 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< destroy(24) (0)

test is a folder on google drive!

zyxmon avatar Jul 06 '16 05:07 zyxmon

We'll to writes to GD and then rely on the updates coming back from Google Drive to update the information that we've cached. That's what this section describes.

This issue is a bit obscure since every single time GDFS emits an IO error exception, it's preceded by a log-item. I can only assume that the FUSE library is raising the error, which must mean that one of the calls is returning data that the FUSE library doesn't like.

My previous comments about how to open it in the foreground not withstanding, this is the absolute minimum that I see in my log when I follow the same debug instructions and simply cd in and *cd *out:

### Mount in foreground

vagrant@vagrant-ubuntu-trusty-64:~$ sudo GD_DEBUG=1 GD_MONITOR_CHANGES=0
gdfs /var/cache/gdfs.creds /mnt/g
2016-07-06 06:21:24,635 [gdrivefs.utility INFO] No extension-mapping was
found.
2016-07-06 06:21:24,682 [__main__ DEBUG] Mounting GD with creds at
[/var/cache/gdfs.creds]: /mnt/g
2016-07-06 06:21:24,683 [gdrivefs.gdfs.gdfuse DEBUG] FUSE options:
{}
2016-07-06 06:21:24,684 [gdrivefs.gdfs.gdfuse DEBUG] PERMS: F=777 E=666
NE=444
2016-07-06 06:21:24,686 [gdrivefs.gdtool.drive DEBUG] Getting authorized
HTTP tunnel.
2016-07-06 06:21:24,686 [gdrivefs.gdtool.drive DEBUG] Got authorized tunnel.
FUSE library version: 2.9.2
nullpath_ok: 0
nopath: 0
utime_omit_ok: 0
unique: 1, opcode: INIT (26), nodeid: 0, insize: 56, pid: 0
INIT: 7.22
flags=0x0000f7fb
max_readahead=0x00020000
2016-07-06 06:21:30,207 [gdrivefs.gdfs.fsutility DEBUG]
--------------------------------------------------
2016-07-06 06:21:30,207 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> init(23)
>>>>>>>>>> (0)
2016-07-06 06:21:30,208 [gdrivefs.gdfs.fsutility DEBUG] DATA: path= [/]
2016-07-06 06:21:30,208 [gdrivefs.gdfs.gdfuse WARNING] We were told not to
monitor changes.
2016-07-06 06:21:30,208 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< init(23)
(0)
   INIT: 7.19
   flags=0x00000011
   max_readahead=0x00020000
   max_write=0x00020000
   max_background=0
   congestion_threshold=0
   unique: 1, success, outsize: 40

### Do a "cd /mnt/g" from another terminal

unique: 2, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 25393
getattr /
2016-07-06 06:21:53,817 [gdrivefs.gdfs.fsutility DEBUG]
--------------------------------------------------
2016-07-06 06:21:53,817 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>>
getattr(4) >>>>>>>>>> (25393)
2016-07-06 06:21:53,817 [gdrivefs.gdfs.fsutility DEBUG] DATA: fh= [None]
 raw_path= [/]
2016-07-06 06:21:54,036 [gdrivefs.cache.cacheclient_base DEBUG]
CacheClientBase(CacheClientBase,28800)
2016-07-06 06:21:54,037 [gdrivefs.cache.cache_agent INFO] Starting
cache-cleanup thread: <gdrivefs.cache.cache_agent.CacheAgent object at
0x7f3fbd24fc50>
2016-07-06 06:21:54,037 [gdrivefs.gdtool.drive INFO] Getting client for
parent-listing.
2016-07-06 06:21:54,038 [gdrivefs.gdtool.drive INFO] Listing entries over
child with ID [0AJFt2OXeDBqSUk9PVA].
2016-07-06 06:21:54,040 [gdrivefs.cache.cache_agent INFO] Cache-cleanup
thread running: <gdrivefs.cache.cache_agent.CacheAgent object at
0x7f3fbd24fc50>
2016-07-06 06:21:54,982 [gdrivefs.gdtool.drive DEBUG] (1) entries were
retrieved.
2016-07-06 06:21:54,983 [gdrivefs.cache.volume DEBUG] Recursively pruning
entry with ID [0AJFt2OXeDBqSUk9PVA].
2016-07-06 06:21:54,984 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<<
getattr(4) (25393)
   unique: 2, success, outsize: 120
unique: 3, opcode: ACCESS (34), nodeid: 1, insize: 48, pid: 25393
access / 01
   unique: 3, success, outsize: 16

### Do a "cd /" and then unmount (followed by SIGHUP to bring it completely down, since we're running in the foreground).

unique: 10, opcode: FORGET (2), nodeid: 1, insize: 48, pid: 0
FORGET 1/1
2016-07-06 06:23:18,412 [gdrivefs.gdfs.fsutility DEBUG]
--------------------------------------------------
2016-07-06 06:23:18,412 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>>
destroy(24) >>>>>>>>>> (0)
2016-07-06 06:23:18,412 [gdrivefs.gdfs.fsutility DEBUG] DATA: path= [/]
2016-07-06 06:23:18,412 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<<
destroy(24) (0)

Can you try the same steps?

dsoprea avatar Jul 06 '16 06:07 dsoprea

When I cd <mount point> I receive Input/Output Error and no more debug message. If I mount GD with the mount point as current dir in another console I get

2016-07-06 12:33:43,872 [gdrivefs.gdtool.drive DEBUG] Getting authorized HTTP tunnel.
2016-07-06 12:33:43,875 [gdrivefs.gdtool.drive DEBUG] Got authorized tunnel.
unique: 2, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 23145
getattr /
2016-07-06 12:34:45,091 [gdrivefs.gdfs.fsutility DEBUG] --------------------------------------------------
2016-07-06 12:34:45,093 [gdrivefs.gdfs.fsutility DEBUG] >>>>>>>>>> getattr(4) >>>>>>>>>> (23145)
2016-07-06 12:34:45,097 [gdrivefs.gdfs.fsutility DEBUG] DATA: fh= [None]  raw_path= [/]
2016-07-06 12:34:45,111 [gdrivefs.cache.cacheclient_base DEBUG] CacheClientBase(CacheClientBase,28800)
2016-07-06 12:34:45,115 [gdrivefs.cache.cache_agent INFO] Starting cache-cleanup thread: <gdrivefs.cache.cache_agent.CacheAgent object at 0xc60990>
2016-07-06 12:34:45,122 [gdrivefs.cache.cache_agent INFO] Cache-cleanup thread running: <gdrivefs.cache.cache_agent.CacheAgent object at 0xc60990>
2016-07-06 12:34:45,121 [gdrivefs.gdtool.drive INFO] Getting client for parent-listing.
2016-07-06 12:34:45,127 [gdrivefs.gdtool.drive INFO] Listing entries over child with ID [0AP09GPqvAIMZUk9PVA].
2016-07-06 12:34:46,366 [gdrivefs.gdtool.drive DEBUG] (1) entries were retrieved.
2016-07-06 12:34:46,372 [gdrivefs.cache.volume DEBUG] Recursively pruning entry with ID [0AP09GPqvAIMZUk9PVA].
2016-07-06 12:34:46,387 [gdrivefs.gdfs.fsutility DEBUG] <<<<<<<<<< getattr(4) (23145)
   unique: 2, success, outsize: 120

when I cd ..

zyxmon avatar Jul 06 '16 09:07 zyxmon