Idle mount fails to open new files

[msh100]

The mount was idle (nothing happened on the log since 03:07) and I attempted to read a file.

15-07-25 13:19:54.832 [DEBUG] [acdcli.fuse] - getattr $PATH/$FILE
15-07-25 13:19:54.845 [DEBUG] [acdcli.fuse] - open $PATH/$FILE
15-07-25 13:19:54.845 [DEBUG] [acdcli.fuse] - read $FILE, ln: 4096 of: 0 fh 1612
15-07-25 13:19:54.853 [DEBUG] [acdcli.fuse] - s: 7979008-524287999; r: 0-4095
15-07-25 13:19:54.853 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
15-07-25 13:19:54.853 [DEBUG] [acdcli.api.common] - Retry 19, waiting -36790.364829 secs
15-07-25 13:19:54.853 [INFO] [acdcli.api.oauth] - Token expired at 2015-07-25 03:05:43.177778.
15-07-25 13:19:54.853 [INFO] [acdcli.api.oauth] - Refreshing authentication token.
15-07-25 13:19:54.854 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): tensile-runway-92512.appspot.com
15-07-25 13:19:54.866 [DEBUG] [acdcli.fuse] - getattr $PARENT
15-07-25 13:19:54.878 [DEBUG] [acdcli.fuse] - getattr $PARENT/$PARENT2
15-07-25 13:19:54.891 [DEBUG] [acdcli.fuse] - getattr $PATH
15-07-25 13:19:54.905 [DEBUG] [acdcli.fuse] - getattr $PATH/$FILE
15-07-25 13:19:54.923 [DEBUG] [acdcli.fuse] - read $FILE, ln: 4096 of: 0 fh 1612
15-07-25 13:19:54.933 [DEBUG] [acdcli.fuse] - s: 7979008-524287999; r: 0-4095
15-07-25 13:19:54.933 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
15-07-25 13:19:54.933 [DEBUG] [acdcli.api.common] - Retry 19, waiting -36790.444845 secs
15-07-25 13:19:54.933 [INFO] [acdcli.api.oauth] - Token expired at 2015-07-25 03:05:43.177778.
15-07-25 13:19:54.934 [INFO] [acdcli.api.oauth] - Refreshing authentication token.
15-07-25 13:19:54.935 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): tensile-runway-92512.appspot.com
15-07-25 13:19:54.954 [DEBUG] [acdcli.fuse] - getattr $PARENT
15-07-25 13:19:54.967 [DEBUG] [acdcli.fuse] - getattr $PARENT/$PARENT2
15-07-25 13:19:54.981 [DEBUG] [acdcli.fuse] - getattr $PATH
15-07-25 13:19:54.996 [DEBUG] [acdcli.fuse] - getattr $PATH/$FILE
15-07-25 13:19:55.012 [DEBUG] [acdcli.fuse] - read $FILE, ln: 4096 of: 0 fh 1612
15-07-25 13:19:55.022 [DEBUG] [acdcli.fuse] - s: 7979008-524287999; r: 0-4095
15-07-25 13:19:55.022 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
15-07-25 13:19:55.022 [DEBUG] [acdcli.api.common] - Retry 19, waiting -36790.533623 secs
15-07-25 13:19:55.022 [INFO] [acdcli.api.oauth] - Token expired at 2015-07-25 03:05:43.177778.
15-07-25 13:19:55.022 [INFO] [acdcli.api.oauth] - Refreshing authentication token.
15-07-25 13:19:55.023 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): tensile-runway-92512.appspot.com
15-07-25 13:19:55.042 [DEBUG] [acdcli.fuse] - getattr $PARENT
15-07-25 13:19:55.055 [DEBUG] [acdcli.fuse] - getattr $PARENT/$PARENT2
15-07-25 13:19:55.068 [DEBUG] [acdcli.fuse] - getattr $PATH
15-07-25 13:19:55.082 [DEBUG] [acdcli.fuse] - getattr $PATH/$FILE
15-07-25 13:19:55.099 [DEBUG] [acdcli.fuse] - read $FILE, ln: 4096 of: 0 fh 1612
15-07-25 13:19:55.108 [DEBUG] [acdcli.fuse] - s: 7979008-524287999; r: 0-4095
15-07-25 13:19:55.108 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
15-07-25 13:19:55.108 [DEBUG] [acdcli.api.common] - Retry 19, waiting -36790.619851 secs
15-07-25 13:19:55.108 [INFO] [acdcli.api.oauth] - Token expired at 2015-07-25 03:05:43.177778.
15-07-25 13:19:55.108 [INFO] [acdcli.api.oauth] - Refreshing authentication token.
15-07-25 13:19:55.110 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): tensile-runway-92512.appspot.com
15-07-25 13:19:55.130 [DEBUG] [acdcli.fuse] - getattr $PARENT
15-07-25 13:19:55.144 [DEBUG] [acdcli.fuse] - getattr $PARENT/$PARENT2
15-07-25 13:19:55.155 [DEBUG] [acdcli.fuse] - getattr $PATH
15-07-25 13:19:55.168 [DEBUG] [acdcli.fuse] - getattr $PATH/$FILE
15-07-25 13:19:55.182 [DEBUG] [acdcli.fuse] - read $FILE, ln: 4096 of: 0 fh 1612
15-07-25 13:19:55.190 [DEBUG] [acdcli.fuse] - s: 7979008-524287999; r: 0-4095
15-07-25 13:19:55.191 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
15-07-25 13:19:55.191 [DEBUG] [acdcli.api.common] - Retry 19, waiting -36790.702399 secs
15-07-25 13:19:55.191 [INFO] [acdcli.api.oauth] - Token expired at 2015-07-25 03:05:43.177778.
15-07-25 13:19:55.191 [INFO] [acdcli.api.oauth] - Refreshing authentication token.
15-07-25 13:19:55.192 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): tensile-runway-92512.appspot.com
15-07-25 13:19:55.211 [DEBUG] [acdcli.fuse] - getattr $PARENT
15-07-25 13:19:55.225 [DEBUG] [acdcli.fuse] - getattr $PARENT/$PARENT2
15-07-25 13:19:55.237 [DEBUG] [acdcli.fuse] - getattr $PATH
15-07-25 13:19:55.250 [DEBUG] [acdcli.fuse] - getattr $PATH/$FILE
15-07-25 13:19:55.265 [DEBUG] [acdcli.fuse] - read $FILE, ln: 4096 of: 0 fh 1612
15-07-25 13:19:55.273 [DEBUG] [acdcli.fuse] - s: 7979008-524287999; r: 0-4095
15-07-25 13:19:55.273 [DEBUG] [acdcli.api.content] - chunk o 0 l 524288000
15-07-25 13:19:55.273 [DEBUG] [acdcli.api.common] - Retry 19, waiting -36790.785022 secs
15-07-25 13:19:55.273 [INFO] [acdcli.api.oauth] - Token expired at 2015-07-25 03:05:43.177778.
15-07-25 13:19:55.274 [INFO] [acdcli.api.oauth] - Refreshing authentication token.
15-07-25 13:19:55.275 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): tensile-runway-92512.appspot.com
15-07-25 13:19:55.294 [DEBUG] [acdcli.fuse] - release $PATH/$FILE, 1612
15-07-25 13:20:02.487 [DEBUG] [acdcli.fuse] - getattr /

After this the file isn't loaded and the client gives up.

Same issue if I try and cp a file from the mount, it will return the errors in fuse above and then create a 0 byte file.

Remounting the drive did resolve the issue.

Note: I am on the dev branch, no idea if this happens on master.

[yadayada]

I think there may be something wrong with the OAuth refresh since I re-introduced the LocalOAuthHandler.

[msh100]

Do you think the LocalOAuthHandler would not encounter this issue?

To test this I will run a mount with both the appspot authentication and local oauth tonight. I have no idea if the Appspot setup even consistently fails yet either.

It's also worth noting that the refresh isn't 100% broken.

15-07-25 17:49:47.156 [DEBUG] [acdcli.fuse] - getattr /$PARENT2
15-07-25 17:49:47.166 [DEBUG] [acdcli.fuse] - getattr /$PARENT2/$PARENT
15-07-25 17:49:47.176 [DEBUG] [acdcli.fuse] - getattr $PATH
15-07-25 17:49:47.188 [DEBUG] [acdcli.fuse] - getattr $PATH/$FILE
15-07-25 17:49:47.201 [DEBUG] [acdcli.fuse] - read $FILE, ln: 16384 of: 4096 fh 7
15-07-25 17:49:47.209 [DEBUG] [acdcli.fuse] - s: 1489062856-1489062855; r: 4096-20479
15-07-25 17:49:47.209 [DEBUG] [acdcli.fuse] - s: 1489006592-1489062855; r: 4096-20479
15-07-25 17:49:47.209 [DEBUG] [acdcli.fuse] - s: 1209036800-1209049087; r: 4096-20479
15-07-25 17:49:47.209 [DEBUG] [acdcli.fuse] - s: 1489062856-1489062855; r: 4096-20479
15-07-25 17:49:47.209 [DEBUG] [acdcli.fuse] - s: 1489059840-1489062855; r: 4096-20479
15-07-25 17:49:47.209 [DEBUG] [acdcli.fuse] - s: 507904-524287999; r: 4096-20479
15-07-25 17:49:47.209 [DEBUG] [acdcli.api.content] - chunk o 4096 l 524288000
15-07-25 17:49:47.209 [DEBUG] [acdcli.api.common] - Retry 0, waiting -12310.152219 secs
15-07-25 17:49:47.210 [INFO] [acdcli.api.oauth] - Token expired at 2015-07-25 14:27:13.185689.
15-07-25 17:49:47.218 [INFO] [acdcli.api.oauth] - Refreshing authentication token.
15-07-25 17:49:47.219 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): tensile-runway-92512.appspot.com
15-07-25 17:49:47.561 [DEBUG] [requests.packages.urllib3.connectionpool] - "POST / HTTP/1.1" 200 1042
15-07-25 17:49:47.564 [INFO] [acdcli.api.oauth] - New token expires at 2015-07-25 18:47:47.218610.
15-07-25 17:49:47.588 [DEBUG] [acdcli.api.common] - GET "https://content-na.drive.amazonaws.com/cdproxy/nodes/$NODE/content"
15-07-25 17:49:47.589 [INFO] [requests.packages.urllib3.connectionpool] - Resetting dropped connection: content-na.drive.amazonaws.com
15-07-25 17:49:50.230 [DEBUG] [requests.packages.urllib3.connectionpool] - "GET /cdproxy/nodes/$NODE/content HTTP/1.1" 206 524288000
15-07-25 17:49:50.232 [DEBUG] [acdcli.fuse] - streamed 16384b
15-07-25 17:49:50.232 [DEBUG] [acdcli.fuse] - read $FILE, ln: 32768 of: 20480 fh 7
15-07-25 17:49:50.243 [DEBUG] [acdcli.fuse] - s: 20480-524292095; r: 20480-53247
15-07-25 17:49:50.402 [DEBUG] [acdcli.fuse] - streamed 32768b

This read absolutely fine after obtaining a new token

[msh100]

After leaving 2 mounts active last night, the one with LocalOAuthHandler worked fine in the morning, and the appspot authentication failed again.

[yadayada]

Could you please try again some time with the latest dev commit? I added a few lines for logging and would like to see the message for the failed refresh.

[msh100]

This is quite a strange one I guess - here's the error which is looped:

15-07-29 00:31:04.103 [INFO] [acdcli.api.oauth] - Token expired at 2015-07-28 04:00:03.164348.
15-07-29 00:31:04.103 [INFO] [acdcli.api.oauth] - Refreshing authentication token.
15-07-29 00:31:04.104 [INFO] [requests.packages.urllib3.connectionpool] - Starting new HTTPS connection (1): tensile-runway-92512.appspot.com
15-07-29 00:31:04.133 [ERROR] [acdcli.fuse] - Creating chunk failed. Code: 1000, msg: [Errno 24] Too many open files
15-07-29 00:31:04.133 [DEBUG] [acdcli.fuse] - FUSE error 70, ECOMM.

Edit: Encountered it a second time.

[msh100]

$ ulimit -n
1024

Same output on both machines I am testing on if this helps. I am not too sure that increasing this is a fix.

[kwloafman]

1024 is awfully low. Try increasing to something reasonable like 32768, especially if you see the 'too many open files' error often.

[msh100]

1024 is default, I think there's a more fundamental issue.

# ls -l /proc/$PID/fd/ | wc -l
1024
# ls -l /proc/$PID/fd/ | grep socket | wc -l
1017
# lsof | grep amazonaws | wc -l
1016

The acd_cli has a huge amount of TCP connections to AWS, I am sure almost all of these should be closed?

[yadayada]

Please try the latest dev commit again.

[msh100]

Thanks for addressing this @yadayada - I will continue to test and let you know results soon.

[msh100]

I am at a point where I am convinced that this is a good working fix.