Azure storage returns empty <Blobs> element

[petr-tichy]

After some testing it looks like the fix in #326 is not sufficient. Sending a response to s3 client with neither CommonPrefixes nor Contents elements is not expected, at least by s3cmd and our backup tool. I suspect that s3proxy would have to handle this internally, issuing the next request(s) and returning it to the client only when it finally contains either CommonPrefixes or Contents

s3cmd fails with

DEBUG: s3cmd version 2.1.0
...

DEBUG: Canonical Request:
GET
/backup/
delimiter=%2F&prefix=data%2Fbackup%2Fsnapshots%2F
host:localhost:8080
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20200820T191251Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
----------------------
DEBUG: signature-v4 headers: {'x-amz-date': '20200820T191251Z', 'Authorization': 'AWS4-HMAC-SHA256 Credential=none/20200820/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=53e4e909916546be4527f62475fcbb2ace0778ded959864eb05f1a7a512aecf4', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855'}
DEBUG: Processing request, please wait...
DEBUG: get_hostname(backup): localhost:8080
DEBUG: ConnMan.get(): re-using connection: http://localhost:8080#1
DEBUG: format_uri(): /backup/?delimiter=%2F&prefix=data%2Fbackup%2Fsnapshots%2F
DEBUG: Sending request method_string='GET', uri='/backup/?delimiter=%2F&prefix=data%2Fbackup%2Fsnapshots%2F', headers={'x-amz-date': '20200820T191251Z', 'Authorization': 'AWS4-HMAC-SHA256 Credential=none/20200820/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=53e4e909916546be4527f62475fcbb2ace0778ded959864eb05f1a7a512aecf4', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855'}, body=(0 bytes)
DEBUG: ConnMan.put(): connection put back to pool (http://localhost:8080#2)
DEBUG: Response:
{'data': b'<?xml version=\'1.0\' encoding=\'UTF-8\'?><ListBucketResult xmlns="h'
         b'ttp://s3.amazonaws.com/doc/2006-03-01/"><Name>backup</Name><Prefi'
         b'x>data/backup/snapshots/</Prefix><MaxKeys>1000</MaxKeys><Marker/>'
         b'<Delimiter>/</Delimiter><IsTruncated>true</IsTruncated><NextMarker>2'
         b'!160!MDAwMDc1IWRhdGEvZmRiYmFja3VwL3NuYXBzaG90cy9zbmFwc2hvdCw2NjM2ODY'
         b'xNDQzNzAzLDY3MjMyOTExNzcxNjksNDYzMTM0MTYzNDYyOCEwMDAwMjghMTYwMS0wMS0'
         b'wMVQwMDowMDowMC4wMDAwMDAwWiE-</NextMarker></ListBucketResult>',
 'headers': {'content-type': 'application/xml; charset=UTF-8',
             'date': 'Thu, 20 Aug 2020 19:12:51 GMT',
             'server': 'Jetty(9.2.z-SNAPSHOT)',
             'transfer-encoding': 'chunked',
             'x-amz-request-id': '4442587FB7D0A2F9'},
 'reason': 'OK',
 'status': 200}

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
    An unexpected error has occurred.
  Please try reproducing the error using
  the latest s3cmd code from the git master
  branch found at:
    https://github.com/s3tools/s3cmd
  and have a look at the known issues list:
    https://github.com/s3tools/s3cmd/wiki/Common-known-issues-and-their-solutions
  If the error persists, please report the
  following lines (removing any private
  info as necessary) to:
   s3tools-bugs@lists.sourceforge.net


!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

Invoked as: /usr/local/bin/s3cmd -c s3cfg --no-ssl --debug ls s3://backup/data/backup/snapshots/
Problem: <class 'IndexError: list index out of range
S3cmd:   2.1.0
python:   3.8.5 (default, Jul 21 2020, 10:48:26)
[Clang 11.0.3 (clang-1103.0.32.62)]
environment LANG=cs_CZ.UTF-8

Traceback (most recent call last):
  File "/usr/local/bin/s3cmd", line 3121, in <module>
    rc = main()
  File "/usr/local/bin/s3cmd", line 3030, in main
    rc = cmd_func(args)
  File "/usr/local/bin/s3cmd", line 152, in cmd_ls
    subcmd_bucket_list(s3, uri, cfg.limit)
  File "/usr/local/bin/s3cmd", line 188, in subcmd_bucket_list
    response = s3.bucket_list(bucket, prefix = prefix, limit = limit)
  File "/usr/local/Cellar/s3cmd/2.1.0/libexec/lib/python3.8/site-packages/S3/S3.py", line 321, in bucket_list
    for truncated, dirs, objects in self.bucket_list_streaming(bucket, prefix, recursive, uri_params, limit):
  File "/usr/local/Cellar/s3cmd/2.1.0/libexec/lib/python3.8/site-packages/S3/S3.py", line 368, in bucket_list_streaming
    uri_params['marker'] = current_prefixes[-1]["Prefix"]
IndexError: list index out of range

Originally posted by @petr-tichy in #326 (comment)

[gaul]

@petr-tichy Could you provide an example of how to create this condition? Do you just list an empty Azure subdirectory?

[petr-tichy]

Well, that is a good question. Unfortunately I'm not yet certain why this happens. I'm unable to replicate this behavior manually with a test account. The reason could be anything from Azure slowing down clients, trying to resolve some consistency issues, or simply a bug or undocumented feature. Accessing our account with other native tools shows no problems, while these seem to handle this gracefully (see below)

We are running FoundationDB backup thru s3proxy to Azure Blob Storage. After the backup was continuously running for several weeks, creating few snapshots, we tried to start expiration and hit this situation. The storage container has currently about 1.4M blobs.

When describing the backups using fdbbackup describe, it first successfully lists some control files, and then tries to list the path data/fdbbackup/snapshots/:

GET /fdbbackup/?max-keys=1000&prefix=data/fdbbackup/snapshots/&delimiter=/&marker=

This prefix currently contains just 8 blobs, but Azure responds first with an empty Blobs and a marker:

[s3proxy] D 08-26 22:02:44.362 S3Proxy-Jetty-17 jclouds.wire:56 |::] << "[0xef][0xbb][0xbf]<?xml version="1.0" encoding="utf-8"?>
<EnumerationResults ServiceEndpoint="https://myaccount.blob.core.windows.net/" ContainerName="fdbbackup">
 <Prefix>data/fdbbackup/snapshots/</Prefix>
 <MaxResults>1000</MaxResults>
 <Blobs />
<NextMarker>2!160!MDAwMDc1IWRhdGEvZmRiYmFja3VwL3NuYXBzaG90cy9zbmFwc2hvdCw2NjM2ODYxNDQzNzAzLDY3MjMyOTExNzcxNjksNDYzMTM0MTYzNDYyOCEwMDAwMjghMTYwMS0wMS0wMVQwMDowMDowMC4wMDAwMDAwWiE-</NextMarker>
</EnumerationResults>"

Using Azure Storage Blobs client library for Python - Version 12.4.0 to list the prefix, I see it really performs two requests. The first response contains the empty <Blobs /> node with continuation marker, and the second has the 8 <Blob> entries (redacted).

Request URL: 'https://myaccount.blob.core.windows.net/fdbbackup?prefix=data%2Ffdbbackup%2Fsnapshots%2F&restype=container&comp=list'
Request method: 'GET'
Request headers:
    'Accept': 'application/xml'
    'x-ms-version': '2019-12-12'
    'x-ms-date': 'Wed, 26 Aug 2020 20:42:33 GMT'
    'x-ms-client-request-id': 'aaedab24-e7dc-11ea-9c08-784f435dbd4f'
    'User-Agent': 'azsdk-python-storage-blob/12.4.0 Python/3.8.2 (macOS-10.15.6-x86_64-i386-64bit)'
    'Authorization': '*****'
Request body:
None
Response status: 200
Response headers:
    'Transfer-Encoding': 'chunked'
    'Content-Type': 'application/xml'
    'Server': 'Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0'
    'x-ms-request-id': '79a39425-a01e-00c5-41e9-7bbabb000000'
    'x-ms-client-request-id': 'aaedab24-e7dc-11ea-9c08-784f435dbd4f'
    'x-ms-version': '2019-12-12'
    'Date': 'Wed, 26 Aug 2020 20:42:34 GMT'
Response content:
<?xml version="1.0" encoding="utf-8"?>
<EnumerationResults ServiceEndpoint="https://myaccount.blob.core.windows.net/" ContainerName="fdbbackup">
 <Prefix>data/fdbbackup/snapshots/</Prefix>
 <Blobs />
 <NextMarker>2!160!MDAwMDc1IWRhdGEvZmRiYmFja3VwL3NuYXBzaG90cy9zbmFwc2hvdCw2NjM2ODYxNDQzNzAzLDY3MjMyOTExNzcxNjksNDYzMTM0MTYzNDYyOCEwMDAwMjghMTYwMS0wMS0wMVQwMDowMDowMC4wMDAwMDAwWiE-</NextMarker>
</EnumerationResults>

Request URL: 'https://myaccount.blob.core.windows.net/fdbbackup?prefix=data%2Ffdbbackup%2Fsnapshots%2F&marker=2%21160%21MDAwMDc1IWRhdGEvZmRiYmFja3VwL3NuYXBzaG90cy9zbmFwc2hvdCw2NjM2ODYxNDQzNzAzLDY3MjMyOTExNzcxNjksNDYzMTM0MTYzNDYyOCEwMDAwMjghMTYwMS0wMS0wMVQwMDowMDowMC4wMDAwMDAwWiE-&restype=container&comp=list'
Request method: 'GET'
Request headers:
    'Accept': 'application/xml'
    'x-ms-version': '2019-12-12'
    'x-ms-date': 'Wed, 26 Aug 2020 20:42:34 GMT'
    'x-ms-client-request-id': 'ab840dee-e7dc-11ea-9c08-784f435dbd4f'
    'User-Agent': 'azsdk-python-storage-blob/12.4.0 Python/3.8.2 (macOS-10.15.6-x86_64-i386-64bit)'
    'Authorization': '*****'
Request body:
None
Response status: 200
Response headers:
    'Transfer-Encoding': 'chunked'
    'Content-Type': 'application/xml'
    'Server': 'Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0'
    'x-ms-request-id': '79a39499-a01e-00c5-25e9-7bbabb000000'
    'x-ms-client-request-id': 'ab840dee-e7dc-11ea-9c08-784f435dbd4f'
    'x-ms-version': '2019-12-12'
    'Date': 'Wed, 26 Aug 2020 20:42:34 GMT'
Response content:
<?xml version="1.0" encoding="utf-8"?>
<EnumerationResults ServiceEndpoint="https://myaccount.blob.core.windows.net/" ContainerName="fdbbackup">
 <Prefix>data/fdbbackup/snapshots/</Prefix>
 <Marker>2!160!MDAwMDc1IWRhdGEvZmRiYmFja3VwL3NuYXBzaG90cy9zbmFwc2hvdCw2NjM2ODYxNDQzNzAzLDY3MjMyOTExNzcxNjksNDYzMTM0MTYzNDYyOCEwMDAwMjghMTYwMS0wMS0wMVQwMDowMDowMC4wMDAwMDAwWiE-</Marker>
 <Blobs>
  <Blob>
   <Name>data/fdbbackup/snapshots/snapshot...</Name>
   ...
  </Blob>
  ...
 </Blobs>
 <NextMarker />
</EnumerationResults>

The code that generated this is:

import sys
import logging
from azure.storage.blob import BlobServiceClient

logger = logging.getLogger('azure.storage.blob')
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(stream=sys.stdout)
logger.addHandler(handler)

blob_service_client = BlobServiceClient.from_connection_string(
    "DefaultEndpointsProtocol=https;AccountName=myaccount;AccountKey=...;EndpointSuffix=core.windows.net",
    logging_enable=True)
container_client = blob_service_client.get_container_client("fdbbackup")
blobs_list = container_client.walk_blobs(name_starts_with="data/fdbbackup/snapshots/")
for blob in blobs_list:
    pass