az upload-batch does not respect timeout

[katcipis]

---

Environment summary

Problem happens with az installed through pip on arch linux and on Docker.

Version:

azure-cli (2.0.28)

acr (2.0.21)
acs (2.0.27)
advisor (0.1.2)
appservice (0.1.28)
backup (1.0.6)
batch (3.1.10)
batchai (0.1.5)
billing (0.1.7)
cdn (0.0.13)
cloud (2.0.12)
cognitiveservices (0.1.11)
command-modules-nspkg (2.0.1)
configure (2.0.14)
consumption (0.2.2)
container (0.1.19)
core (2.0.28)
cosmosdb (0.1.19)
dla (0.0.18)
dls (0.0.19)
eventgrid (0.1.10)
extension (0.0.9)
feedback (2.1.0)
find (0.2.8)
interactive (0.3.16)
iot (0.1.17)
keyvault (2.0.19)
lab (0.0.17)
monitor (0.1.2)
network (2.0.24)
nspkg (3.0.1)
profile (2.0.19)
rdbms (0.0.12)
redis (0.2.11)
reservations (0.1.1)
resource (2.0.24)
role (2.0.20)
servicefabric (0.0.10)
sql (2.0.22)
storage (2.0.26)
vm (2.0.27)

Python location '/usr/bin/python'
Extensions directory '/root/.azure/cliextensions'

Python (Linux) 3.5.2 (default, Nov 23 2017, 16:37:01)
[GCC 5.4.0 20160609]

I'm using the upload-batch like this:

az storage blob upload-batch --destination-path $remotedir --destination $container --source $localdir --account-name $account --account-key $accountkey --timeout $timeout

Because I'm getting some timeouts on uploading a big file (~300mb). After setting the timeout the behavior remains the same, even the time it takes to timeout is the same. It does not seem that the parameter is applied. I tested with "3600" as the parameter and the time was:

0.41user 0.39system 6:06.91elapsed 0%CPU (0avgtext+0avgdata 44056maxresident)k

With "600" :

0.39user 0.32system 5:47.10elapsed 0%CPU (0avgtext+0avgdata 46268maxresident)k

Both fails almost after the same elapsed time with a timeout error:

ERROR: ('Connection aborted.', timeout('The write operation timed out',))
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 601, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 357, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/usr/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/usr/lib/python3.5/http/client.py", line 936, in _send_output
    self.send(message_body)
  File "/usr/lib/python3.5/http/client.py", line 908, in send
    self.sock.sendall(data)
  File "/usr/lib/python3.5/ssl.py", line 891, in sendall
    v = self.send(data[count:])
  File "/usr/lib/python3.5/ssl.py", line 861, in send
    return self._sslobj.write(data)
  File "/usr/lib/python3.5/ssl.py", line 586, in write
    return self._sslobj.write(data)
socket.timeout: The write operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 376, in send
    timeout=timeout
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 639, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/retry.py", line 357, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/packages/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 601, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 357, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/usr/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/usr/lib/python3.5/http/client.py", line 936, in _send_output
    self.send(message_body)
  File "/usr/lib/python3.5/http/client.py", line 908, in send
    self.sock.sendall(data)
  File "/usr/lib/python3.5/ssl.py", line 891, in sendall
    v = self.send(data[count:])
  File "/usr/lib/python3.5/ssl.py", line 861, in send
    return self._sslobj.write(data)
  File "/usr/lib/python3.5/ssl.py", line 586, in write
    return self._sslobj.write(data)
requests.packages.urllib3.exceptions.ProtocolError: ('Connection aborted.', timeout('The write operation timed out',))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/common/storageclient.py", line 252, in _perform_request
    response = self._httpclient.perform_request(request)
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/common/_http/httpclient.py", line 92, in perform_request
    proxies=self.proxies)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 468, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 576, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 426, in send
    raise ConnectionError(err, request=request)
requests.exceptions.ConnectionError: ('Connection aborted.', timeout('The write operation timed out',))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/knack/cli.py", line 194, in invoke
    cmd_result = self.invocation.execute(args)
  File "/usr/local/lib/python3.5/dist-packages/azure/cli/core/commands/__init__.py", line 342, in execute
    six.reraise(*sys.exc_info())
  File "/usr/lib/python3/dist-packages/six.py", line 686, in reraise
    raise value
  File "/usr/local/lib/python3.5/dist-packages/azure/cli/core/commands/__init__.py", line 315, in execute
    result = cmd(params)
  File "/usr/local/lib/python3.5/dist-packages/azure/cli/core/commands/__init__.py", line 175, in __call__
    return super(AzCliCommand, self).__call__(*args, **kwargs)
  File "/usr/local/lib/python3.5/dist-packages/knack/commands.py", line 109, in __call__
    return self.handler(*args, **kwargs)
  File "/usr/local/lib/python3.5/dist-packages/azure/cli/core/__init__.py", line 349, in default_command_handler
    result = op(**command_args)
  File "/usr/local/lib/python3.5/dist-packages/azure/cli/command_modules/storage/operations/blob.py", line 181, in storage_blob_upload_batch
    if_none_match=if_none_match, timeout=timeout)
  File "/usr/local/lib/python3.5/dist-packages/azure/cli/command_modules/storage/operations/blob.py", line 258, in upload_blob
    return type_func[blob_type]()
  File "/usr/local/lib/python3.5/dist-packages/azure/cli/command_modules/storage/operations/blob.py", line 251, in upload_block_blob
    return client.create_blob_from_path(**create_blob_args)
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/blob/blockblobservice.py", line 404, in create_blob_from_path
    timeout=timeout)
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/blob/blockblobservice.py", line 555, in create_blob_from_stream
    initialization_vector=iv
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/blob/_upload_chunking.py", line 79, in _upload_blob_chunks
    raise f.exception()
  File "/usr/lib/python3.5/concurrent/futures/thread.py", line 55, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/blob/_upload_chunking.py", line 204, in process_chunk
    return self._upload_chunk_with_progress(chunk_offset, chunk_bytes)
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/blob/_upload_chunking.py", line 218, in _upload_chunk_with_progress
    range_id = self._upload_chunk(chunk_offset, chunk_data)
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/blob/_upload_chunking.py", line 263, in _upload_chunk
    timeout=self.timeout,
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/blob/blockblobservice.py", line 954, in _put_block
    self._perform_request(request)
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/common/storageclient.py", line 354, in _perform_request
    raise ex
  File "/usr/local/lib/python3.5/dist-packages/azure/multiapi/storage/v2017_07_29/common/storageclient.py", line 294, in _perform_request
    raise AzureException(ex.args[0])
azure.common.AzureException: ('Connection aborted.', timeout('The write operation timed out',))

[williexu]

@katcipis hmm it seems like your timeout values in seconds, (3600, 600) are both larger than the amount of time than the command took (6mins ~ 360).

Can you try a smaller timeout?
Also keep in mind that the timeout is applied on a block by block basis, it is not the time taken for the full blob to upload.

[katcipis]

@williexu the command took less time because it failed with a timeout error, a timeout that by definition is smaller than the timeout values I passed as a parameter (as you pointed out), hence the bug =)

[williexu]

@katcipis I see your point, thought you were trying to restrict the timeout even further.
This issue likely lies with the sdk.

@zezha-msft, the CLI passes along the timeout parameter to the sdk: specifically, create_blob_from_path() for blob blobs.
Would you know why this is not the timeout being applied to the block upload?

[zezha-msft]

Hi @williexu, the timeout that @katcipis is hitting is the socket timeout, not the server timeout that is being passed to the SDK. Socket timeout is hit when the network is not stable, it is set when creating the BlockBlobService. Thanks.

[katcipis]

@zezha-msft Yeah it really impresses me the miracles that AWS S3 can do with my unstable network since I'm able to upload much larges files to S3 with the same network =) (I'm actually trying to migrate working S3 code to Azure).

[katcipis]

I see on the stack trace a **self.sock.sendall(data)"" call, taking a look on the Python docs:

Changed in version 3.5: The socket timeout is no more reset each time data is sent successfully.
The socket timeout is now the maximum total duration to send all data

I searched for this because my tcpdump indicated a normal bi-directional flow of data until the exception occurs, so although my upload speed is just 100 KB/s, it is steady, there are no network errors. This problem will occur with any kind of network since it will be a function of the file size (if the network is 100 times better it will fail with a 100 times bigger file).

My Python version is 3.5.2 (as stated on the beginning of the bug report)

[williexu]

@katcipis the issue lies with the default socket_timeout we use in the storage sdk: constant
As you noticed, the behavior with sendall() in Python 3 causes this default to be unreasonable.

Please be assured that we are working on a solution for the sdk, that will allow stable data-transfer, independent of the network speed (within limits) or file size. I will update this thread when our change is out.

[williexu]

@katcipis we have exposed the socket timeout for blob uploads/downloads in #6046. This will be released 5/7 in our CLI with version 2.0.32. In the meantime, feel free to try out the new fix using dev-setup, our edge builds, or docker-automated builds

There will also be a change in the python sdk to better enable transfer of data for python3 users of the sdk directly.

[galvesribeiro]

We are hitting the exactly same problem using latest CLI. --socket-timeout is not being reported as deprecated. What is the suggestion nowadays to have a simple file upload to work?