Endless loop in rclone lsd command with in azure blob storage

Suspected Bug
1

What is the problem you are having with rclone?

I can't list container in azure blob storage after performed point in time restore on one of containers.
So before this problem occurred I executed point in time restore command:

az storage blob restore --account-name $storage_account --time-to-restore "$formatted_date" --blob-range $container ${container}-0 $sub_conf $rg_conf

So according to documentation: Perform a point-in-time restore on block blob data - Azure Storage | Microsoft Learn
I'm specifying the container range with adding -0 suffix in my command as you can observe.

To include the entire container named myContainer in the range for a restore use start range 
myContainer and end range myContainer-0. This shows how adding '-0' as a suffix to the container 
name for the end range value includes everything in the container for the restore.

As a result PITR finished successfully without any exception but when I'm trying to list container I'm getting stack into the loop while rclone trying to point to my container with -0 suffix as next container during the pagination.

For some reason rclone define it as container anyhow.

Also when I'm listing container with az client everything works as container:

az storage container list --account-name {account_name} --sas-token "{token}"  | jq -r ".[].name"

and output is as expected without container with -0 suffix.
So I guess something is wrong on Rclone side. WDYT?

Run the command 'rclone version' and share the full output of the command.

rclone v1.61.1

  • os/version: ubuntu 22.04 (64 bit)
  • os/kernel: 5.15.0-56-generic (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.19.4
  • go/linking: static
  • go/tags: none

Which cloud storage system are you using? (eg Google Drive)

Azure Blob Storage

The command you were trying to run (eg rclone copy /tmp remote:tmp)

rclone lsd {alias}:  -vv --dump requests,responses

The rclone config contents with secrets removed.

[azure]
type = azureblob
account_name = ${account_name}
sas_url = https://${account_name}.blob.core.windows.net?${sas_token}

A log from the command with the -vv flag

2023/01/04 21:17:25 DEBUG : rclone: Version "v1.61.1" starting with parameters ["rclone" "lsd" "azure:" "--config" "/tmp/.rclone-backup-to-azure.conf" "-vv" "--dump" "requests,responses"]
2023/01/04 21:17:25 DEBUG : Creating backend with remote "azure:"
2023/01/04 21:17:25 DEBUG : Using config file from "/tmp/.rclone-backup-to-azure.conf"
2023/01/04 21:17:25 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2023/01/04 21:17:25 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/01/04 21:17:25 DEBUG : HTTP REQUEST (req 0xc0008d3a00)
2023/01/04 21:17:25 DEBUG : GET /?comp=list&include=deleted%2Cmetadata&maxresults=5000&{sas_token} HTTP/1.1
Host: {account_name}.blob.core.windows.net
User-Agent: rclone/v1.61.1
Accept: application/xml
x-ms-version: 2020-10-02
Accept-Encoding: gzip

2023/01/04 21:17:25 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/01/04 21:17:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/01/04 21:17:25 DEBUG : HTTP RESPONSE (req 0xc0008d3a00)
2023/01/04 21:17:25 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: application/xml
Date: Wed, 04 Jan 2023 20:17:24 GMT
Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
X-Ms-Request-Id: {}
X-Ms-Version: 2020-10-02

<?xml version="1.0" encoding="utf-8"?>
<EnumerationResults ServiceEndpoint="https://{account_name}.blob.core.windows.net/">
	<MaxResults>5000</MaxResults>
		<Container>
			<Name>container_i_retored</Name>
			<Properties>
				<Last-Modified>Fri, 28 Oct 2022 10:15:00 GMT</Last-Modified>
				<Etag>"some_tag"</Etag>
				<LeaseStatus>unlocked</LeaseStatus>
				<LeaseState>broken</LeaseState>
				<DefaultEncryptionScope>$account-encryption-key</DefaultEncryptionScope>
				<DenyEncryptionScopeOverride>false</DenyEncryptionScopeOverride>
				<HasImmutabilityPolicy>false</HasImmutabilityPolicy>
				<HasLegalHold>false</HasLegalHold>
				<ImmutableStorageWithVersioningEnabled>false</ImmutableStorageWithVersioningEnabled>
			</Properties>
			<Metadata />
		</Container>
	</Containers>
	<NextMarker>/{account_name}/container_i_retored-0/NextMarker>
</EnumerationResults>

2023/01/04 21:17:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/01/04 21:17:25 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/01/04 21:17:25 DEBUG : HTTP REQUEST (req 0xc0008d3a00)
2023/01/04 21:17:25 DEBUG : GET /?comp=list&include=deleted%2Cmetadata&maxresults=5000&{sas_token} HTTP/1.1
Host: {account_name}.blob.core.windows.net
User-Agent: rclone/v1.61.1
Accept: application/xml
x-ms-version: 2020-10-02
Accept-Encoding: gzip

2023/01/04 21:17:25 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/01/04 21:17:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/01/04 21:17:25 DEBUG : HTTP RESPONSE (req 0xc0008d3a00)
2023/01/04 21:17:25 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: application/xml
Date: Wed, 04 Jan 2023 20:17:25 GMT
Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
X-Ms-Request-Id: {}
X-Ms-Version: 2020-10-02

<?xml version="1.0" encoding="utf-8"?>
<EnumerationResults ServiceEndpoint="https://{account_name}.blob.core.windows.net/">
	<MaxResults>5000</MaxResults>
		<Container>
			<Name>container_i_retored</Name>
			<Properties>
				<Last-Modified>Fri, 28 Oct 2022 10:15:00 GMT</Last-Modified>
				<Etag>"some_tag"</Etag>
				<LeaseStatus>unlocked</LeaseStatus>
				<LeaseState>broken</LeaseState>
				<DefaultEncryptionScope>$account-encryption-key</DefaultEncryptionScope>
				<DenyEncryptionScopeOverride>false</DenyEncryptionScopeOverride>
				<HasImmutabilityPolicy>false</HasImmutabilityPolicy>
				<HasLegalHold>false</HasLegalHold>
				<ImmutableStorageWithVersioningEnabled>false</ImmutableStorageWithVersioningEnabled>
			</Properties>
			<Metadata />
		</Container>
	</Containers>
	<NextMarker>/{account_name}/container_i_retored-0/NextMarker>
</EnumerationResults>

2023/01/04 21:17:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/01/04 21:17:25 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/01/04 21:17:25 DEBUG : HTTP REQUEST (req 0xc0008d3a00)
2023/01/04 21:17:25 DEBUG : GET /?comp=list&include=deleted%2Cmetadata&maxresults=5000&{sas_token} HTTP/1.1
Host: {account_name}.blob.core.windows.net
User-Agent: rclone/v1.61.1
Accept: application/xml
x-ms-version: 2020-10-02
Accept-Encoding: gzip

2023/01/04 21:17:25 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/01/04 21:17:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/01/04 21:17:25 DEBUG : HTTP RESPONSE (req 0xc0008d3a00)
2023/01/04 21:17:25 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: application/xml
Date: Wed, 04 Jan 2023 20:17:26 GMT
Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
X-Ms-Request-Id: {}
X-Ms-Version: 2020-10-02

<?xml version="1.0" encoding="utf-8"?>
<EnumerationResults ServiceEndpoint="https://{account_name}.blob.core.windows.net/">
	<MaxResults>5000</MaxResults>
		<Container>
			<Name>container_i_retored</Name>
			<Properties>
				<Last-Modified>Fri, 28 Oct 2022 10:15:00 GMT</Last-Modified>
				<Etag>"some_tag"</Etag>
				<LeaseStatus>unlocked</LeaseStatus>
				<LeaseState>broken</LeaseState>
				<DefaultEncryptionScope>$account-encryption-key</DefaultEncryptionScope>
				<DenyEncryptionScopeOverride>false</DenyEncryptionScopeOverride>
				<HasImmutabilityPolicy>false</HasImmutabilityPolicy>
				<HasLegalHold>false</HasLegalHold>
				<ImmutableStorageWithVersioningEnabled>false</ImmutableStorageWithVersioningEnabled>
			</Properties>
			<Metadata />
		</Container>
	</Containers>
	<NextMarker>/{account_name}/container_i_retored-0/NextMarker>
</EnumerationResults>

2023/01/04 21:17:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
ENDLESS
2

Just run client command list containers with --debug flag to simulate same request you do (2023/01/04 21:17:25 DEBUG : GET /?comp=list&include=deleted%2Cmetadata&maxresults=5000&{sas_token} HTTP/1.1 )

az storage container list --account-name {account_name} --sas-token "{token}" --include-deleted --include-metadata  --num-results 5000 --debug

And I can see next request that is done by azure client:

urllib3.connectionpool: Starting new HTTPS connection (1): {account_name}.blob.core.windows.net:443
urllib3.connectionpool: https://{account_name}.blob.core.windows.net:443 "GET /?comp=list&maxresults=5000&include=metadata,deleted&{sas_token} HTTP/1.1" 200 None
urllib3.connectionpool: https://{account_name}.blob.core.windows.net:443 "GET /?comp=list&marker=/{account_name}/{container_i_restored}-0&maxresults=5000&include=metadata,deleted&{sas_token} HTTP/1.1" 200 None
cli.knack.cli: Event: CommandInvoker.OnTransformResult [<function _resource_group_transform at 0x7fa8bab7d6c0>, <function _x509_from_base64_to_hex_transform at 0x7fa8bab7d750>]

so marker is the same here so not sure if is it something with azure or you missing something during handling of this requests.. because az client is not going into the loop

3

Looks like sdk problem, we with teammate tried to compile rclone and some code examples from sdk docs (azblob package - github.com/Azure/azure-sdk-for-go/sdk/storage/azblob - Go Packages) and this is also in loop.
We will try to manage it on that side

After fix of sdk works as expected

4

For rclone v1.61 we started using the new SDK. Can you see if rclone v1.60 has the same problem?

What does the fix of the SDK look like? It's worth reporting a bug on the upstream repo and sending a PR they are responsive to both.

5

I'll be able to check it tomorrow. But I recall we had some another issue with azure in older version.
So I'll come back tomorrow

1 Like
6

This is the kind of thing I should get into a point release if possible, so more details appreciated :slight_smile:

7

Hi, I'm sorry for delay with response, had some busy days.
As conclusion I can say 2 things

  1. It works fine with version
rclone v1.59.0
- os/version: ubuntu 22.04 (64 bit)
- os/kernel: 5.15.0-57-generic (x86_64)
- os/type: linux
- os/arch: 386
- go/version: go1.18.3
- go/linking: static
- go/tags: none
  1. We with teammate created a PR to azure skd repo, you can join to discussion here
    [azblob] fix pager nextpage endless loop by dimagv · Pull Request #19773 · Azure/azure-sdk-for-go · GitHub

So you can decide either to revert version or wait for fix (we made a work around in our code to avoid this loop)

8

Thanks for the link.

Your patch looks good to me.

I'll see whether anyone else has trouble with this issue before putting it in a point release.

The SDK is rather a moving target at the moment, so updating the SDK for a point release of rclone might break other things.

9

Ok, got it.
Just FYI, I tried reproduce it on different storage accounts and it was always reproducing after performing point in time restore, so I believe you can get this also.

Thanks for support.

1 Like
10

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.