acd_cli icon indicating copy to clipboard operation
acd_cli copied to clipboard

Published 20 hours ago • verified publisher icon yadayada

FUSE mount stops working after some time

Open msh100 opened this issue 8 years ago • 54 comments

I am not too sure what's going on here, I recently updated to the version of acd_cli from master, and have issues with the FUSE read mount. This has happened more than once now.

The last two lines of this log just loop thousands and thousands of times.

16-03-06 06:39:26.891 [DEBUG] [acdcli.acd_fuse] - -> statfs / ()
16-03-06 06:39:26.892 [DEBUG] [acdcli.acd_fuse] - <- statfs {'f_blocks': 209715200, 'f_namemax': 256, 'f_bavail': 189484774, 'f_bfree': 189484774, 'f_frsize': 524288, 'f_bsize': 524288}
16-03-06 06:39:26.892 [DEBUG] [acdcli.acd_fuse] - -> statfs / ()
16-03-06 06:39:26.893 [DEBUG] [acdcli.acd_fuse] - <- statfs {'f_blocks': 209715200, 'f_namemax': 256, 'f_bavail': 189484774, 'f_bfree': 189484774, 'f_frsize': 524288, 'f_bsize': 524288}
16-03-06 06:39:26.893 [DEBUG] [acdcli.acd_fuse] - -> statfs / ()
16-03-06 06:39:26.893 [DEBUG] [acdcli.acd_fuse] - <- statfs {'f_blocks': 209715200, 'f_namemax': 256, 'f_bavail': 189484774, 'f_bfree': 189484774, 'f_frsize': 524288, 'f_bsize': 524288}
16-03-06 06:39:26.894 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
16-03-06 06:39:26.894 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-06 06:39:27.176 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
16-03-06 06:39:27.176 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-06 06:39:27.177 [DEBUG] [acdcli.acd_fuse] - -> statfs / ()
16-03-06 06:39:27.177 [DEBUG] [acdcli.acd_fuse] - <- statfs {'f_blocks': 209715200, 'f_namemax': 256, 'f_bavail': 189484774, 'f_bfree': 189484774, 'f_frsize': 524288, 'f_bsize': 524288}
16-03-06 06:39:27.177 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
16-03-06 06:39:27.178 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-06 06:39:27.178 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
16-03-06 06:39:27.178 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-06 06:39:27.811 [DEBUG] [acdcli.acd_fuse] - -> getattr /$PATH (None,)

msh100 avatar Mar 06 '16 12:03 msh100

I experienced this for 3 consecutive days and have reverted to a commit I think I was on before, https://github.com/yadayada/acd_cli/commit/8997b8c3697d1f7b2b31f3c0bb4150004eb1e321

msh100 avatar Mar 07 '16 09:03 msh100

I was about to post the same issue. I'm not sure yet of what's going on, but I randomly need to unmount and mount again my acd folder. It seems to be something 'locked'. All processes are waiting: ie the df -h or ls /path/to/acd/mount are taking a very long time (between a few minutes and hours). @msh100 are you experiencing the same thing?

maximegaillard avatar Mar 07 '16 10:03 maximegaillard

@maximegaillard no - it would just not work (bad address error iirc)

msh100 avatar Mar 07 '16 10:03 msh100

same problem here, bad address error. After remounting everything works again for a few hours :( how can I revert to the commit you're talking about @msh100 ?

strickes avatar Mar 07 '16 12:03 strickes

@strickes I did the following:

pip3 install --upgrade git+https://github.com/yadayada/acd_cli.git@8997b8c3697d1f7b2b31f3c0bb4150004eb1e321

As I know 8997b8c is a good working commit for me.

msh100 avatar Mar 07 '16 13:03 msh100

thanks, it seems to work again :) I think the write speed is not the same as with the newest commit, but it's stable again.

strickes avatar Mar 07 '16 13:03 strickes

spoke too soon, after an hour of being mounted: root@linux01:/mnt/acd# ll ls: reading directory .: Bad address total 0

strickes avatar Mar 07 '16 14:03 strickes

Yes same here it appears

16-03-07 15:05:04.329 [DEBUG] [acdcli.acd_fuse] - -> getattr /$DIRECTORY (None,)
16-03-07 15:05:04.329 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-07 15:05:04.329 [DEBUG] [acdcli.acd_fuse] - -> getattr /$DIRECTORY (None,)
16-03-07 15:05:04.329 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-07 15:05:04.330 [DEBUG] [acdcli.acd_fuse] - -> getattr /$DIRECTORY (None,)
16-03-07 15:05:04.330 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-07 15:05:04.330 [DEBUG] [acdcli.acd_fuse] - -> getattr /$DIRECTORY (None,)
16-03-07 15:05:04.330 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-07 15:05:04.331 [DEBUG] [acdcli.acd_fuse] - -> getattr /$DIRECTORY (None,)
16-03-07 15:05:04.331 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-07 15:05:04.331 [DEBUG] [acdcli.acd_fuse] - -> getattr /$DIRECTORY (None,)
16-03-07 15:05:04.331 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-07 15:05:04.332 [DEBUG] [acdcli.acd_fuse] - -> getattr /$DIRECTORY (None,)
16-03-07 15:05:04.332 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-07 15:05:04.333 [DEBUG] [acdcli.acd_fuse] - -> getattr /$DIRECTORY (None,)
16-03-07 15:05:04.333 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-07 15:05:11.467 [DEBUG] [acdcli.acd_fuse] - -> destroy / ()
16-03-07 15:05:11.468 [DEBUG] [acdcli.acd_fuse] - <- destroy None

Same issue as latest commit, I have absolutely no idea how to proceed.

msh100 avatar Mar 07 '16 15:03 msh100

@yadayada is there anything we can do now to improve logging for this? I am fairly sure that the logs I have already handed over are quite unhelpful.

msh100 avatar Mar 07 '16 15:03 msh100

I experience the same problems as Maximegaillard. Ls takes very long and in Cyberduck I receive timeout errors. I am using acd_cli on two Debian systems one works great so far and the other produces these occasional errors time by time, but at least once a day. How do I find out which commit I use on the machine that works great so far?

Niklasmaximilian avatar Mar 07 '16 17:03 Niklasmaximilian

is there anything we can do now to improve logging for this?

Are these excerpts from the log file? If so, could you please mount in debug+foreground mode; you should get the print_exc calls output then.

yadayada avatar Mar 07 '16 18:03 yadayada

Sure, will do. Will update you asap.

msh100 avatar Mar 07 '16 18:03 msh100

I am experiencing this issue too. Only updated today and didn't notice this issue. Has anyone found a stable commit?

hjone72 avatar Mar 08 '16 02:03 hjone72

I am still monitoring this and it has not happened again however has got me thinking - acd_cli has been working flawlessly for months, and out of the blue this happens and just happens to line up with an update I did, when I revert it happens again.

My suspicion at the moment is a malformed API response from Amazon.

In the meantime I will keep logging and if there's nothing in a few days I guess this issue should be closed assuming Amazon is the cause of the issue.

msh100 avatar Mar 08 '16 22:03 msh100

Did you do anything specific to fix it? Mine seems to be happening every night

hjone72 avatar Mar 09 '16 21:03 hjone72

Short update: Issue of non-working fuse mount is still there and suddenly appeared on my second box as well.

acd_cli on this second box was not touched or updated since september 2015, because I never had any issues.

Is there anythign I can do to improve logs?

Niklasmaximilian avatar Mar 10 '16 06:03 Niklasmaximilian

I have the feeling that this issue is something similar as this issue: https://github.com/yadayada/acd_cli/issues/124

I always get this output when I try to umount my acd mount again.

fusermount: failed to unmount /mount/directory: Device or resource busy

Only killing the process helps...

Niklasmaximilian avatar Mar 10 '16 07:03 Niklasmaximilian

This just started for me today, but only on a single box.

An older box with an older acd_cli is fine :/

geekcroft avatar Mar 11 '16 18:03 geekcroft

Can anyone experiencing this also provide logs as mentioned above? The data I have been able to get so far is not very informative.

msh100 avatar Mar 12 '16 14:03 msh100

So mount with acdcli mount --debug <mount folder>?

SullyTheUnusual avatar Mar 12 '16 14:03 SullyTheUnusual

eh, acd_cli --debug mount --foreground <mountpoint>

You may want to make it log somewhere all the output

msh100 avatar Mar 12 '16 14:03 msh100

I did a --debug mount and got the same messages as @msh100 spammed over and over.

I have re-pulled from the 1.3.0 master release and it seems a lot more settled - then again -i0 helped too.

geekcroft avatar Mar 12 '16 14:03 geekcroft

Ok, here's my rsync errors: rsync: recv_generator: failed to stat "/home/sullytheunusual/acd/Backups/Backups/Pictures/2004/E. May/PICT3502.JPG": Bad address (14) rsync: write failed on "/home/sullytheunusual/acd/Backups/Backups/Pictures/2004/A. January/PICT2947.JPG": Bad address (14) rsync error: error in file IO (code 11) at receiver.c(393) [receiver=3.1.1]

Here's a link to my log file: https://dl.dropboxusercontent.com/u/83188234/acd_cli.log

yadayada here. This is an unrelated issue with rsync's error handling.

SullyTheUnusual avatar Mar 12 '16 15:03 SullyTheUnusual

Hi, unfortunately the problem still persists. I took some logs today. I use acd_cli in combination with EncFs. I never had problems in the past, but since 10 or 11 days it is not stable anymore.

16-03-13 14:39:41.212 [DEBUG] [acdcli.acd_fuse] - <- open 948
16-03-13 14:39:41.213 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (948,)
16-03-13 14:39:41.213 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:39:41.213 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (948,)
16-03-13 14:39:41.213 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:39:41.214 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (948,)
16-03-13 14:39:41.214 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:39:41.214 [DEBUG] [acdcli.acd_fuse] - -> release /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (948,)
16-03-13 14:39:41.214 [DEBUG] [acdcli.acd_fuse] - -> open /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 ('0x8000',)
16-03-13 14:39:41.215 [DEBUG] [acdcli.acd_fuse] - <- open 949
16-03-13 14:39:41.215 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (16384, 0, 949)
16-03-13 14:39:41.216 [DEBUG] [acdcli.acd_fuse] - <- release None
16-03-13 14:39:41.217 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
16-03-13 14:39:41.217 [DEBUG] [acdcli.api.backoff_req] - Retry 0, waiting 0.595219s
16-03-13 14:39:41.813 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=0-524287999\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer \r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:39:43.285 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:39:43.705 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:39:43.714 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:39:43.715 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (4096, 0, 949)
16-03-13 14:39:43.716 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
16-03-13 14:39:43.716 [DEBUG] [acdcli.api.backoff_req] - Retry 1, waiting 0.761135s
16-03-13 14:39:44.479 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=0-524287999\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer \r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:39:45.397 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:39:45.398 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:39:45.398 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:39:45.398 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (4096, 131072, 949)
16-03-13 14:39:45.399 [DEBUG] [acdcli.api.content] - chunk o 131072 l 524288000
16-03-13 14:39:45.399 [DEBUG] [acdcli.api.backoff_req] - Retry 2, waiting 2.737401s
16-03-13 14:39:48.139 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=131072-524419071\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer Atza|I\r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:39:48.524 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:39:48.525 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:39:48.525 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:39:48.525 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (4096, 131072, 949)
16-03-13 14:39:48.526 [DEBUG] [acdcli.api.content] - chunk o 131072 l 524288000
16-03-13 14:39:48.526 [WARNING] [acdcli.api.backoff_req] - Waiting 5.306609s because of error(s).
16-03-13 14:39:48.526 [DEBUG] [acdcli.api.backoff_req] - Retry 3, waiting 5.306609s
16-03-13 14:39:53.835 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=131072-524419071\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer Atza|\r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:39:54.102 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:39:54.103 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:39:54.103 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:39:54.103 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
16-03-13 14:39:54.104 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1457773456.433, 'st_mode': 16895, 'st_atime': 1457876394.1041048, 'st_ctime': 1442076409.886}
16-03-13 14:39:54.104 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (949,)
16-03-13 14:39:54.104 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:39:54.104 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (949,)
16-03-13 14:39:54.105 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:39:54.105 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (949,)
16-03-13 14:39:54.105 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:39:54.105 [DEBUG] [acdcli.acd_fuse] - -> release /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (949,)
16-03-13 14:39:54.106 [DEBUG] [acdcli.acd_fuse] - <- release None
16-03-13 14:39:54.555 [DEBUG] [acdcli.acd_fuse] - -> getattr /6ENeGl6NiZaV3g0zNkHRR-qs (None,)
16-03-13 14:39:54.556 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1457382338.328, 'st_mode': 16895, 'st_atime': 1457876394.556431, 'st_ctime': 1442085885.693}
16-03-13 14:39:54.556 [DEBUG] [acdcli.acd_fuse] - -> getattr /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1 (None,)
16-03-13 14:39:54.557 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1454217796.617, 'st_mode': 16895, 'st_atime': 1457876394.5577571, 'st_ctime': 1454217795.477}
16-03-13 14:39:54.558 [DEBUG] [acdcli.acd_fuse] - -> getattr /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi (None,)
16-03-13 14:39:54.559 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1457421336.232, 'st_mode': 16895, 'st_atime': 1457876394.5596607, 'st_ctime': 1454217796.596}
16-03-13 14:39:54.560 [DEBUG] [acdcli.acd_fuse] - -> getattr /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (None,)
16-03-13 14:39:54.561 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_mode': 33206, 'st_ctime': 1454223568.932, 'st_nlink': 1, 'st_mtime': 1454224808.386, 'st_atime': 1457876394.5612557, 'st_size': 1462574402}
16-03-13 14:39:54.561 [DEBUG] [acdcli.acd_fuse] - -> open /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 ('0x8000',)
16-03-13 14:39:54.562 [DEBUG] [acdcli.acd_fuse] - <- open 950
16-03-13 14:39:54.666 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (4096, 0, 950)
16-03-13 14:39:54.667 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
16-03-13 14:39:54.668 [DEBUG] [acdcli.api.backoff_req] - Retry 4, waiting 3.738953s
16-03-13 14:39:58.411 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=0-524287999\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer Atza|\r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:39:59.254 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:39:59.255 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:39:59.255 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:39:59.255 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (4096, 131072, 950)
16-03-13 14:39:59.257 [DEBUG] [acdcli.api.content] - chunk o 131072 l 524288000
16-03-13 14:39:59.418 [WARNING] [acdcli.api.backoff_req] - Waiting 21.162848s because of error(s).
16-03-13 14:39:59.418 [DEBUG] [acdcli.api.backoff_req] - Retry 5, waiting 21.162848s
16-03-13 14:40:20.590 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=131072-524419071\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer Atza\r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:40:21.118 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:40:21.119 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:40:21.119 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:40:21.120 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
16-03-13 14:40:21.121 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1457773456.433, 'st_mode': 16895, 'st_atime': 1457876421.1211026, 'st_ctime': 1442076409.886}
16-03-13 14:40:21.121 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (950,)
16-03-13 14:40:21.121 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:40:21.122 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (950,)
16-03-13 14:40:21.122 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:40:21.122 [DEBUG] [acdcli.acd_fuse] - -> flush /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (950,)
16-03-13 14:40:21.122 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-13 14:40:21.122 [DEBUG] [acdcli.acd_fuse] - -> release /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (950,)
16-03-13 14:40:21.123 [DEBUG] [acdcli.acd_fuse] - <- release None
16-03-13 14:40:22.145 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
16-03-13 14:40:22.146 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1457773456.433, 'st_mode': 16895, 'st_atime': 1457876422.1460435, 'st_ctime': 1442076409.886}
16-03-13 14:40:22.146 [DEBUG] [acdcli.acd_fuse] - -> getattr /6ENeGl6NiZaV3g0zNkHRR-qs (None,)
16-03-13 14:40:22.147 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1457382338.328, 'st_mode': 16895, 'st_atime': 1457876422.1471164, 'st_ctime': 1442085885.693}
16-03-13 14:40:22.147 [DEBUG] [acdcli.acd_fuse] - -> getattr /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1 (None,)
16-03-13 14:40:22.148 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1454217796.617, 'st_mode': 16895, 'st_atime': 1457876422.1481872, 'st_ctime': 1454217795.477}
16-03-13 14:40:22.149 [DEBUG] [acdcli.acd_fuse] - -> getattr /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi (None,)
16-03-13 14:40:22.149 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1457421336.232, 'st_mode': 16895, 'st_atime': 1457876422.1496294, 'st_ctime': 1454217796.596}
16-03-13 14:40:22.150 [DEBUG] [acdcli.acd_fuse] - -> getattr /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (None,)
16-03-13 14:40:22.150 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_mode': 33206, 'st_ctime': 1454223568.932, 'st_nlink': 1, 'st_mtime': 1454224808.386, 'st_atime': 1457876422.1508038, 'st_size': 1462574402}
16-03-13 14:40:22.151 [DEBUG] [acdcli.acd_fuse] - -> open /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 ('0x8000',)
16-03-13 14:40:22.151 [DEBUG] [acdcli.acd_fuse] - <- open 951
16-03-13 14:40:22.151 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (16384, 0, 951)
16-03-13 14:40:22.152 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
16-03-13 14:40:22.152 [WARNING] [acdcli.api.backoff_req] - Waiting 33.370684s because of error(s).
16-03-13 14:40:22.152 [DEBUG] [acdcli.api.backoff_req] - Retry 6, waiting 33.370684s
16-03-13 14:40:55.530 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=0-524287999\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer Atza|\r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:40:55.832 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:40:55.832 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:40:55.832 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:40:55.833 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (4096, 0, 951)
16-03-13 14:40:55.880 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
16-03-13 14:40:55.880 [WARNING] [acdcli.api.backoff_req] - Waiting 12.891159s because of error(s).
16-03-13 14:40:55.880 [DEBUG] [acdcli.api.backoff_req] - Retry 7, waiting 12.891159s
16-03-13 14:41:08.783 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=0-524287999\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer Atza|\r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:41:09.964 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:41:09.966 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:41:09.966 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:41:09.966 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (4096, 131072, 951)
16-03-13 14:41:09.968 [DEBUG] [acdcli.api.content] - chunk o 131072 l 524288000
16-03-13 14:41:09.968 [WARNING] [acdcli.api.backoff_req] - Waiting 83.829851s because of error(s).
16-03-13 14:41:09.968 [DEBUG] [acdcli.api.backoff_req] - Retry 8, waiting 83.829851s
16-03-13 14:42:33.882 [INFO] [acdcli.api.backoff_req] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content"
16-03-13 14:42:33.891 [INFO] [requests.packages.urllib3.connectionpool] - Resetting dropped connection: content-na.drive.amazonaws.com
16-03-13 14:42:33.892 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (702): content-na.drive.amazonaws.com
send: b'CONNECT content-na.drive.amazonaws.com:443 HTTP/1.0\r\n'
send: b'\r\n'
send: b'GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1\r\nHost: content-na.drive.amazonaws.com\r\nAccept-Encoding: gzip, deflate\r\nRange: bytes=131072-524419071\r\nConnection: keep-alive\r\nUser-Agent: acdcli.api/0.8.9 python-requests/2.9.1\r\nAuthorization: Bearer Atza|\r\nAccept: */*\r\n\r\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Content-Type header: Date header: Server header: x-amzn-RequestId header: Content-Length header: Connection 16-03-13 14:42:35.108 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/bncUSLbmTiaDq9HnC07gIw/content HTTP/1.1" 500 30
16-03-13 14:42:35.109 [ERROR] [acdcli.acd_fuse] - get: RequestError: 500, {"message":"Internal failure"}
16-03-13 14:42:35.109 [DEBUG] [acdcli.acd_fuse] - <- read 28
16-03-13 14:42:35.109 [DEBUG] [acdcli.acd_fuse] - -> read /6ENeGl6NiZaV3g0zNkHRR-qs/Z1akLBynrP5iyuYgXod9zYL1/eLOKp062O8G5ga4KUlVe4IQi/mPqI-,JeTuk9lXWDTLsT4D-TvVQ,UrOcK73GZjQN7GtHj8-S61nyfkE77YA5J1V2jU7 (4096, 131072, 951)
16-03-13 14:42:35.110 [DEBUG] [acdcli.api.content] - chunk o 131072 l 524288000
16-03-13 14:42:35.110 [WARNING] [acdcli.api.backoff_req] - Waiting 170.212323s because of error(s).
16-03-13 14:42:35.111 [DEBUG] [acdcli.api.backoff_req] - Retry 9, waiting 170.212323s

Niklasmaximilian avatar Mar 13 '16 13:03 Niklasmaximilian

@Niklasmaximilian See #283. Please contact Amazon's support.

yadayada avatar Mar 13 '16 15:03 yadayada

I am finding that mine is getting unmounted every night. At first I thought it was related to #283 like @yadayada suggested. I found a few files that were 'corrupted' or had been lost (they couldn't be downloaded via web interface nor acd_cli). I have deleted those files and I still find I get unmounted.

I find I get these two entries a LOT

16-03-17 07:43:04.238 [DEBUG] [acdcli.acd_fuse] - <- release '[Unhandled Exception]'
16-03-17 07:43:04.248 [DEBUG] [acdcli.acd_fuse] - -> getattr /KxjzY5gOLel2bzkAMpHYUhuc (None,)

When it was a corrupted file I would find an "Internal Failure" near an attempted access of a file, since removing all those corrupted files I can't find "Internal Failure" anywhere in the logs.

I notice that it gets unmounted when uploading to ACD.

I am assuming the issue is relating to something in these lines here:

16-03-17 07:43:04.015 [DEBUG] [acdcli.acd_fuse] - -> getattr /KxjzY5gOLel2bzkAMpHYUhuc/y4IG9rJF1U9g,oVYUevZ2CP0/aKgvV2jharEnVcSp88XumRG1/OGKPZCtXp4jCozPUnCOta7nf/Q3omaXkXVmPD0FE4nORxb7cMyPbuOlntQGJ4Y47uhbdJCG92dme0BD9WXByWwKoDV35 (None,)
16-03-17 07:43:04.019 [DEBUG] [acdcli.acd_fuse] - <- getattr '[Unhandled Exception]'
16-03-17 07:43:04.235 [DEBUG] [acdcli.acd_fuse] - -> flush /KxjzY5gOLel2bzkAMpHYUhuc/y4IG9rJF1U9g,oVYUevZ2CP0/aKgvV2jharEnVcSp88XumRG1/OGKPZCtXp4jCozPUnCOta7nf/Q3omaXkXVmPD0FE4nORxb7cMyPbuOlntQGJ4Y47uhbdJCG92dme0BD9WXByWwKoDV35 (406,)
16-03-17 07:43:04.236 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-17 07:43:04.236 [DEBUG] [acdcli.acd_fuse] - -> flush /KxjzY5gOLel2bzkAMpHYUhuc/y4IG9rJF1U9g,oVYUevZ2CP0/aKgvV2jharEnVcSp88XumRG1/OGKPZCtXp4jCozPUnCOta7nf/Q3omaXkXVmPD0FE4nORxb7cMyPbuOlntQGJ4Y47uhbdJCG92dme0BD9WXByWwKoDV35 (406,)
16-03-17 07:43:04.237 [DEBUG] [acdcli.acd_fuse] - <- flush None
16-03-17 07:43:04.237 [DEBUG] [acdcli.acd_fuse] - -> release /KxjzY5gOLel2bzkAMpHYUhuc/y4IG9rJF1U9g,oVYUevZ2CP0/aKgvV2jharEnVcSp88XumRG1/OGKPZCtXp4jCozPUnCOta7nf/Q3omaXkXVmPD0FE4nORxb7cMyPbuOlntQGJ4Y47uhbdJCG92dme0BD9WXByWwKoDV35 (406,)
16-03-17 07:43:04.238 [DEBUG] [acdcli.acd_fuse] - <- release '[Unhandled Exception]'
16-03-17 07:43:04.248 [DEBUG] [acdcli.acd_fuse] - -> getattr /KxjzY5gOLel2bzkAMpHYUhuc (None,)

But I can't see why, as the file Q3omaXkXVmPD0FE4nORxb7cMyPbuOlntQGJ4Y47uhbdJCG92dme0BD9WXByWwKoDV35 was accessed only a few lines before successfully.

This morning I have had it unmount several times on me. Here is a link to the log: https://dl.dropboxusercontent.com/u/6390060/acd_cli.log

Hopefully this helps. Thanks,

hjone72 avatar Mar 16 '16 22:03 hjone72

@hjone72

Which OS are you using? Please also give me a log obtained by using acdcli -d mount -fg /mount/point.

Addendum: I did not suggest the original issue was related to #238.

yadayada avatar Mar 17 '16 05:03 yadayada

I'm having the same issue as @hjone72 It's getting unmounted while uploading files with acd_cli upload. If I don't upload it's stable. I'm using Ubuntu 14.10 server (minimal).

ghost avatar Mar 17 '16 12:03 ghost

That may line up with the issues I had and sounds plausible.

However I have not encountered it since and have been uploading :confused:

msh100 avatar Mar 17 '16 12:03 msh100

I was using rclone to upload (as I can limit bandwidth) but "committing" with an acd_cli sync - and this was causing the issue too.

However, this was only on a newer acd_cli build on a newer VPS. I moved back to my older box with an older acd_cli version on it, and I now have 0 issues.

On Thu, Mar 17, 2016 at 12:55 PM, Marcus Stewart Hughes < [email protected]> wrote:

That may line up with the issues I had and sounds plausible.

However I have not encountered it since and have been uploading [image: :confused:]

— You are receiving this because you commented. Reply to this email directly or view it on GitHub https://github.com/yadayada/acd_cli/issues/290#issuecomment-197866948

geekcroft avatar Mar 17 '16 13:03 geekcroft