Cyberduck Mountain Duck CLI

#7785 closed defect (thirdparty)

Server side copies read timeouts

Reported by: david cole Owned by: dkocher
Priority: normal Milestone:
Component: openstack Version: 4.4.3
Severity: normal Keywords: read timeout
Cc: jason.pereira@…, joel.wright@… Architecture:
Platform: Mac OS X 10.9

Description

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)

Change History (2)

comment:1 Changed on Feb 11, 2014 at 1:55:49 PM by dkocher

  • Component changed from core to openstack
  • Owner set to dkocher
  • Summary changed from openstack swift server side copies read timeouts to Server side copies read timeouts

comment:2 Changed on Feb 12, 2014 at 11:23:06 AM by dkocher

  • Resolution set to thirdparty
  • Status changed from new to closed

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.

Note: See TracTickets for help on using tickets.
swiss made software