Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Server side copies read timeouts #7785

Closed
cyberduck opened this issue Feb 11, 2014 · 2 comments
Closed

Server side copies read timeouts #7785

cyberduck opened this issue Feb 11, 2014 · 2 comments
Assignees
Labels
bug fixed openstack OpenStack Swift Protocol Implementation
Milestone

Comments

@cyberduck
Copy link
Collaborator

e2f2ab4 created the issue

Hi,

One of our users reported many read timeout mesages when duplicating a large container in Cyberduck 4.4.3

Using the duplicate function in Cyberduck on Openstack swift, the log drawer shows that a server side copy is being performed - eg a PUT operation with the X-Copy-From header set to another location within the same cluster.

This works well for small files, but does time out on larger files with the default timeout set. The customer saw a timeout with 1000MB files and I can see it testing with a 4000MB files. I think around 800MB is the threshold on our Openstack clusters. Here are the debug log messages showing an example timeout on a single object which is quite big:

2014-02-11 10:41:17,652 [background-1] INFO  ch.cyberduck.core.Session - PUT /v1/AUTH_abcdefabcdefabc12312312312312312/dupe%20me%204 HTTP/1.1
2014-02-11 10:41:17,652 [background-1] INFO  ch.cyberduck.core.Session - X-Auth-Token: cbacbacbacbacbacabcbac
2014-02-11 10:41:17,652 [background-1] INFO  ch.cyberduck.core.Session - Content-Length: 0
2014-02-11 10:41:17,652 [background-1] INFO  ch.cyberduck.core.Session - Host: proxy-01.example.com
2014-02-11 10:41:17,652 [background-1] INFO  ch.cyberduck.core.Session - Connection: Keep-Alive
2014-02-11 10:41:17,652 [background-1] INFO  ch.cyberduck.core.Session - User-Agent: Cyberduck/4.4.3 (Mac OS X/10.9) (x86_64)
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.impl.client.DefaultHttpClient - Attempt 1 to execute request
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Sending request: PUT /v1/AUTH_abcdefabcdefabc12312312312312312/dupe%20me%204 HTTP/1.1
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.headers - >> PUT /v1/AUTH_abcdefabcdefabc12312312312312312/dupe%20me%204 HTTP/1.1
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.headers - >> X-Auth-Token: cbacbacbacbacbacabcbac
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.headers - >> Content-Length: 0
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.headers - >> Host: proxy-01.example.com
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.headers - >> Connection: Keep-Alive
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.headers - >> User-Agent: Cyberduck/4.4.3 (Mac OS X/10.9) (x86_64)
2014-02-11 10:41:17,653 [background-1] DEBUG org.apache.http.headers - >> Accept-Encoding: gzip,deflate
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Receiving response: HTTP/1.1 201 Created
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.headers - << HTTP/1.1 201 Created
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.headers - << Content-Length: 0
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.headers - << Content-Type: text/html; charset=UTF-8
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.headers - << Date: Tue, 11 Feb 2014 10:41:14 GMT
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.headers - << Connection: keep-alive
2014-02-11 10:41:18,510 [background-1] INFO  ch.cyberduck.core.Session - HTTP/1.1 201 Created
2014-02-11 10:41:18,510 [background-1] INFO  ch.cyberduck.core.Session - Content-Length: 0
2014-02-11 10:41:18,510 [background-1] INFO  ch.cyberduck.core.Session - Content-Type: text/html; charset=UTF-8
2014-02-11 10:41:18,510 [background-1] INFO  ch.cyberduck.core.Session - Date: Tue, 11 Feb 2014 10:41:14 GMT
2014-02-11 10:41:18,510 [background-1] INFO  ch.cyberduck.core.Session - Connection: keep-alive
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.impl.client.DefaultHttpClient - Connection can be kept alive indefinitely
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection [id: 24][route: {s}->https://proxy-01.example.com] can be kept alive indefinitely
2014-02-11 10:41:18,510 [background-1] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection released: [id: 24][route: {s}->https://proxy-01.example.com][total kept alive: 3; route allocated: 2 of 2147483647; total allocated: 3 of 2147483647]
2014-02-11 10:41:18,511 [background-1] DEBUG ch.cyberduck.core.transfer.CopyTransfer - Transfer file /dupe me/CentOS-5.8-x86_64-bin-DVD-1of2.iso with options TransferOptions{resumeRequested=false, reloadRequested=false, quarantine=true}
2014-02-11 10:41:18,511 [background-1] INFO  ch.cyberduck.core.Session - Copying CentOS-5.8-x86_64-bin-DVD-1of2.iso to CentOS-5.8-x86_64-bin-DVD-1of2.iso
2014-02-11 10:41:18,512 [background-1] WARN  ch.cyberduck.core.openstack.SwiftRegionService - Unknown region null in authentication context
2014-02-11 10:41:18,512 [background-1] WARN  ch.cyberduck.core.openstack.SwiftRegionService - Fallback to first region found null
2014-02-11 10:41:18,512 [background-1] WARN  ch.cyberduck.core.openstack.SwiftRegionService - No CDN management endpoint found for region null
2014-02-11 10:41:18,513 [background-1] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection request: [route: {s}->https://proxy-01.example.com][total kept alive: 22; route allocated: 21 of 2147483647; total allocated: 22 of 2147483647]
2014-02-11 10:41:18,513 [background-1] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection leased: [id: 1][route: {s}->https://proxy-01.example.com][total kept alive: 21; route allocated: 21 of 2147483647; total allocated: 22 of 2147483647]
2014-02-11 10:41:18,513 [background-1] DEBUG org.apache.http.impl.client.DefaultHttpClient - Stale connection check
2014-02-11 10:41:18,514 [background-1] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: best-match
2014-02-11 10:41:18,514 [background-1] DEBUG org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context
2014-02-11 10:41:18,514 [background-1] DEBUG org.apache.http.client.protocol.RequestTargetAuthentication - Target auth state: UNCHALLENGED
2014-02-11 10:41:18,514 [background-1] DEBUG org.apache.http.client.protocol.RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2014-02-11 10:41:18,515 [background-1] INFO  ch.cyberduck.core.Session - PUT /v1/AUTH_abcdefabcdefabc12312312312312312/dupe%20me%204/CentOS-5.8-x86_64-bin-DVD-1of2.iso HTTP/1.1
2014-02-11 10:41:18,515 [background-1] INFO  ch.cyberduck.core.Session - X-Copy-From: dupe%20me/CentOS-5.8-x86_64-bin-DVD-1of2.iso
2014-02-11 10:41:18,515 [background-1] INFO  ch.cyberduck.core.Session - X-Auth-Token: cbacbacbacbacbacabcbac
2014-02-11 10:41:18,515 [background-1] INFO  ch.cyberduck.core.Session - Content-Length: 0
2014-02-11 10:41:18,515 [background-1] INFO  ch.cyberduck.core.Session - Host: proxy-01.example.com
2014-02-11 10:41:18,515 [background-1] INFO  ch.cyberduck.core.Session - Connection: Keep-Alive
2014-02-11 10:41:18,516 [background-1] INFO  ch.cyberduck.core.Session - User-Agent: Cyberduck/4.4.3 (Mac OS X/10.9) (x86_64)
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.impl.client.DefaultHttpClient - Attempt 1 to execute request
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Sending request: PUT /v1/AUTH_abcdefabcdefabc12312312312312312/dupe%20me%204/CentOS-5.8-x86_64-bin-DVD-1of2.iso HTTP/1.1
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.headers - >> PUT /v1/AUTH_abcdefabcdefabc12312312312312312/dupe%20me%204/CentOS-5.8-x86_64-bin-DVD-1of2.iso HTTP/1.1
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.headers - >> X-Copy-From: dupe%20me/CentOS-5.8-x86_64-bin-DVD-1of2.iso
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.headers - >> X-Auth-Token: cbacbacbacbacbacabcbac
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.headers - >> Content-Length: 0
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.headers - >> Host: proxy-01.example.com
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.headers - >> Connection: Keep-Alive
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.headers - >> User-Agent: Cyberduck/4.4.3 (Mac OS X/10.9) (x86_64)
2014-02-11 10:41:18,516 [background-1] DEBUG org.apache.http.headers - >> Accept-Encoding: gzip,deflate

<< paused here >>

2014-02-11 10:41:48,521 [background-1] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Connection 0.0.0.0:61315<->193.203.66.230:443 closed
2014-02-11 10:41:48,522 [background-1] DEBUG org.apache.http.impl.client.DefaultHttpClient - Closing the connection.
2014-02-11 10:41:48,522 [background-1] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Connection 0.0.0.0:61315<->193.203.66.230:443 closed
2014-02-11 10:41:48,522 [background-1] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Connection 0.0.0.0:61315<->193.203.66.230:443 shut down
2014-02-11 10:41:48,523 [background-1] DEBUG org.apache.http.impl.conn.DefaultClientConnection - Connection 0.0.0.0:61315<->193.203.66.230:443 closed
2014-02-11 10:41:48,523 [background-1] DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager - Connection released: [id: 1][route: {s}->https://proxy-01.example.com][total kept alive: 21; route allocated: 20 of 2147483647; total allocated: 21 of 2147483647]
2014-02-11 10:41:48,534 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidChangeBackingProperties:
2014-02-11 10:41:48,534 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillMove:
2014-02-11 10:41:48,534 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillExitVersionBrowser:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidUpdate:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidResize:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidMiniaturize:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidEnterFullScreen:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidExitFullScreen:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidChangeOcclusionState:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidMove:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidEndSheet:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillOrderOffScreen:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidOrderOnScreen:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidExpose:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidEndLiveResize:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillMiniaturize:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidExitVersionBrowser:
2014-02-11 10:41:48,535 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidOrderOffScreen:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillEnterVersionBrowser:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidChangeScreenProfile:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidEnterVersionBrowser:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidDeminiaturize:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillOrderOnScreen:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowDidChangeScreen:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillStartLiveResize:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillBeginSheet:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:validRequestorForSendType:returnType:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:windowWillReturnFieldEditor:toObject:
2014-02-11 10:41:48,536 [background-1] DEBUG org.rococoa.callback - No method for selector:window:willEncodeRestorableState:
2014-02-11 10:41:48,554 [main] DEBUG org.rococoa.callback - No method for selector:window:willPositionSheet:usingRect:
2014-02-11 10:41:48,887 [background-1] DEBUG ch.cyberduck.ui.cocoa.SheetController - Await sheet dismiss
2014-02-11 10:42:14,267 [Finalizer] DEBUG org.rococoa - Draining autorelease pool
2014-02-11 10:42:14,282 [Finalizer] DEBUG org.rococoa - Draining autorelease pool
2014-02-11 10:42:14,291 [Finalizer] DEBUG org.rococoa - Draining autorelease pool
2014-02-11 10:42:14,301 [Finalizer] DEBUG org.rococoa - Draining autorelease pool
2014-02-11 10:42:14,303 [main] DEBUG org.rococoa.callback - No method for selector:undoManagerForWindow:
2014-02-11 10:42:14,303 [main] DEBUG org.rococoa.callback - No method for selector:windowWillReturnUndoManager:
2014-02-11 10:42:14,307 [Finalizer] DEBUG org.rococoa - Draining autorelease pool
2014-02-11 10:42:14,316 [Finalizer] DEBUG org.rococoa - Draining autorelease pool
2014-02-11 10:42:16,396 [main] DEBUG ch.cyberduck.ui.cocoa.SheetController - Close sheet with button Continue
2014-02-11 10:42:16,734 [background-1] WARN  ch.cyberduck.ui.action.AbstractTransferWorker - Ignore transfer failure Cannot copy CentOS-5.8-x86_64-bin-DVD-1of2.iso (/dupe me/CentOS-5.8-x86_64-bin-DVD-1of2.iso). Read timed out.

This has similarities to Ticket #7732 " Bulk delete can appear to timeout." - is that ticket, the older version of swift did not send any data during the long running bulk-delete, but the sending of white space in more recent versions of swift means that the client will not timeout - this is not the case for the Server Side copy. I have looked at the swift CHANGELOG and I don't see an improvement to the X-Copy-From logic to send whitespace or workaround this issue there.

Is there anything we can do in Cyberduck. One theory - If we know how large the file is we could estimate how long the server side copy is likely to take and set the timeout for that operation (if preference timeout is < estimate)

@cyberduck
Copy link
Collaborator Author

@dkocher commented

I conclude that Swift should implement a similar workaround as in bulk operations. Adding different timeouts in Cyberduck depending on the expected workload sounds very error prone to me.

@cyberduck
Copy link
Collaborator Author

@AliveDevil commented

Fixed with 9e65aca.

@iterate-ch iterate-ch locked as resolved and limited conversation to collaborators Nov 26, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug fixed openstack OpenStack Swift Protocol Implementation
Projects
None yet
Development

No branches or pull requests

2 participants