Deletion of <blob> from <account/container> failed: 0 completed (used SAS, discovery not completed)

[skywalkerisnull]

Storage Explorer Version: 1.17 Build Number: 20201211.10 Platform/OS: Windows 10 Architecture: x64 Regression From: unknown

Bug Description

Attempt to delete any blob in the container results in an error message.

Steps to Reproduce

1. Connect to the blob using a connection string: DefaultEndpointsProtocol=https;AccountName=testuser;AccountKey=<64byte base64 key>;BlobEndpoint=https://custom.domain.io/testuser (Additional notes, the blob is behind a proxy and the container is operating on port 11002, the same issue appears if I connect direct to the local IP address and the port without going through the proxy.
2. Upload the blob by click and dragging a file.
3. Confirm the blob uploaded correctly by downloading and inspecting the file
4. Click delete.
5. Option about soft delete is presented. Click yes
6. Error message

Expected Experience

The blob to be deleted and no error message

Actual Experience

The blob does not get deleted and I get an error message

Additional Context

The blob is an IoT blob deployed using this guide: https://docs.microsoft.com/en-us/azure/iot-edge/how-to-deploy-blob?view=iotedge-2018-06 It is generally connected to via a proxy server that will server a valid TLS certificate on 443. It is possible to connect (from my workstation) directly to VM that is running the blob pod/container via the VM IP address on port 11002.

Logs with tokens redacted and domains sanitized:

Error:

Deletion of 'blob.json' from 'account/container' failed: 0 completed (used SAS, discovery not completed)
Started at: 11/02/2021, 3:23:09 pm, Duration: 1 seconds

Details:

{
  "message": "\"UnexpectedQuit\""
}

AzCopy Command:

$env:AZCOPY_CRED_TYPE = "Anonymous";
./azcopy.exe remove "https://custom.domain.io/testuser/test01/blob.json?sv=2019-12-12&se=2021-03-13T05%3A15%3A58Z&sr=c&sp=rdl&sig=REDACTED" --recursive;
$env:AZCOPY_CRED_TYPE = "";

Azure Storage Explorer logs:

[2021-02-11T05:15:58.694Z] (20888) <INFO> Activity added {
  title: "Queued deletion of 'blob.json' from 'testuser/test01' (using SAS)",
  message: '',
  speed: undefined,
  progress: undefined,
  status: undefined,
  actions: []
}
[2021-02-11T05:15:59.717Z] (20888) <INFO> Activity finalized {
  title: "Deletion of 'blob.json' from 'testuser/test01' failed",
  message: '0 completed (used SAS, discovery not completed)\n' +
    'Started at: 11/02/2021, 3:15:58 pm, Duration: 1 seconds',
  speed: undefined,
  progress: undefined,
  status: undefined,
  actions: [ 'Details...', 'Copy AzCopy Command to Clipboard' ]
}
[2021-02-11T05:23:05.047Z] (20888) <INFO> Activity added {
  title: "Queued deletion of 'blob.json' from 'testuser/test01' (using SAS)",
  message: '',
  speed: undefined,
  progress: undefined,
  status: undefined,
  actions: []
}
[2021-02-11T05:23:09.045Z] (20888) <INFO> Activity finalized {
  title: "Deletion of 'blob.json' from 'testuser/test01' failed",
  message: '0 completed (used SAS, discovery not completed)\n' +
    'Started at: 11/02/2021, 3:23:08 pm, Duration: 1 seconds',
  speed: undefined,
  progress: undefined,
  status: undefined,
  actions: [ 'Details...', 'Copy AzCopy Command to Clipboard' ]
}
[2021-02-11T05:33:43.140Z] (20888) <INFO> Activity added {
  title: "Queued deletion of 'blob.json' from 'testuser/test01' (using SAS)",
  message: '',
  speed: undefined,
  progress: undefined,
  status: undefined,
  actions: []
}
[2021-02-11T05:33:44.167Z] (20888) <INFO> Activity finalized {
  title: "Deletion of 'blob.json' from 'testuser/test01' failed",
  message: '0 completed (used SAS, discovery not completed)\n' +
    'Started at: 11/02/2021, 3:33:43 pm, Duration: 1 seconds',
  speed: undefined,
  progress: undefined,
  status: undefined,
  actions: [ 'Details...', 'Copy AzCopy Command to Clipboard' ]
}

Azure Blob IoT logs:

[2021-02-11 05:21:40.472] [info    ] [tid 360] WossProvider : {0} Cache Auto-Refresh Running Stats: Total autoRefreshed={1}, Currently enqueued={2} Outstanding refreshes={3}, p0="Account", p1="0", p2="0", p3="0"
[2021-02-11 05:22:02.193] [info    ] [tid 409] WossProvider : {0} Cache Auto-Refresh Running Stats: Total autoRefreshed={1}, Currently enqueued={2} Outstanding refreshes={3}, p0="Container", p1="0", p2="0", p3="0"
[2021-02-11 05:23:01.972] [info    ] [tid 64] Info: Accepting {0} request for '{1}'. RemoteEndPoint='{2}', Via='{3}', Expect='{4}', Connection='{5}', Version='{6}', ClientRequestId='{7}', UserAgent='{8}' DurationStayedInQueueInMs='{9}', RemainingRequestsInQueueAtEnqueue='{10}', RemainingRequestsInQueueAtDequeue='{11}', WasInHighPriorityQueue='{12}', ToSetKeepAliveToFalse='{13}', ActiveWorkerThreads='{14}', ActiveCompletionThreads='{15}' PassedInActivityId={16}, EnqueueTime={17}, DequeueTime={18}, RequestTraceActvityId = '{19}', p0="GET", p1="http://blob02.infarm.io:11002/testuser/?restype=service&comp=properties", p2="192.168.2.169:45936", p3="", p4="", p5="", p6="2019-12-12", p7="d163b151-f5fc-4a9c-b89b-89b3bd17449a", p8="MicrosoftAzure Storage Explorer,", p9="0.0403", p10="0", p11="0", p12="False", p13="False", p14="1", p15="0", p16="null", p17="2021-02-11T05:23:01.9722994Z", p18="2021-02-11T05:23:01.9723348Z", p19="4eb496e8-69c5-45be-a725-b7c4e0ab8a32"
[2021-02-11 05:23:01.976] [info    ] [tid 432] Perf: PerfCounters: Account={0} Operation={1} on Container={2} with Status={3} RequestHeaderSize={4} RequestSize={5} ResponseHeaderSize={6} ResponseSize={7} ErrorResponseByte={8} TimeInMs={9} ProcessingTimeInMs={10} UserTimeoutInMs={11} OperationTimeoutInMs={12} MaxAllowedTimeoutInMs={13} SlaUsedInMs={14} ReadLatencyInMs={15} WriteLatencyInMs={16} ClientIP={17} UserAgent='{18}' RequestVersion='{19}' ProcessorVersionUsed='{20}' RequestUrl='{21}' ClientRequestId='{22}' MeasurementStatus={23} HttpStatusCode={24} TotalFeTimeInMs={25} TotalTableServerTimeInMs={26} TotalTableServerRoundTripCount={27} TotalPartitionWaitTimeInMs={28} TotalXStreamTimeInMs={29} TotalXStreamRoundTripCount={30} SmbOpLockBreakLatency={31} LastTableServerInstanceName={32} LastTableServerErrorCode={33} TotalAccountCacheWaitTimeInMs={34} TotalContainerCacheWaitTimeInMs={35} InternalStatus={36} RequestContentType='{37}' ResponseContentType='{38}' PartitionKey='{39}' ItemsReturned='{40}' BatchOperationCount='{41}' LastXStreamErrorCode={42} AuthenticationType='{43}' AccountConcurrentReq='{44}' OverallConcurrentReq='{45}' Range='{46}' EntityType='{47}' {48} LastTSPartition={49} TotalXCacheTimeInMs={50} TotalXCacheRoundTripCount={51} TotalTableServerOnlyTimeInMicroSeconds={52} TotalAuthTimeInMs={53} AuthenticationTimeInMs={54} AuthorizationTimeInMs={55} GetAuthenticationDataTimeInMs={56} GetAuthorizationDataTimeInMs={57} VnetPolicyCheckTimeInMs={58} PerfFeatureFlags={59}, p0="testuser", p1="GetBlobServiceProperties", p2="", p3="Success", p4="776", p5="0", p6="185", p7="601", p8="0", p9="3.9005", p10="3.7955", p11="922337203685477", p12="30000", p13="30000", p14="0", p15="0", p16="0.105", p17="192.168.2.169:45936", p18="MicrosoftAzure Storage Explorer, 1.17.0, win32 azsdk-js-storageblob/12.2.1 (NODE-VERSION v12.13.0; Windows_NT 10.0.19042)", p19="2019-12-12", p20="2019-12-12", p21="http://custom.domain.io:80/testuser/?restype=service&comp=properties", p22="d163b151-f5fc-4a9c-b89b-89b3bd17449a", p23="Success", p24="200", p25="3.795", p26="0", p27="0", p28="0", p29="0", p30="0", p31="0", p32="", p33="0", p34="0", p35="0", p36="ExpectedSuccess", p37="", p38="application/xml", p39="", p40="0", p41="0", p42="0", p43="NA", p44="", p45="1", p46="", p47="", p48="", p49="", p50="0", p51="0", p52="0", p53="0.28", p54="0.25", p55="0.03", p56="0", p57="0", p58="0", p59="null"

[skywalkerisnull]

A workaround for this is to create a custom domain with an associated A/AAAA record that follows the pattern of *.blob.custom.domain.io where the ".blob" component is mandatory and what the AzCopy is looking for in the URL.

[JasonYeMSFT]

I have setup a testing edge device and it did reveal multiple bugs in our code. At the meantime, AzCopy is aware of the domain name bug and is working on a fix. Both fixes will have to wait until 1.21.0.

[MRayermannMSFT]

@skywalkerisnull 1.21.0 is now live and gradually rolling out. If you haven't received the update yet, you can manually download it from https://storageexplorer.com

Please give that version a try and let us know if your issue is now fixed. Thanks!

[skywalkerisnull]

@MRayermannMSFT I have downloaded 1.21.0 and will now setup a IoT blob storage that is not using the .blob. domain name and check the deleting blob functionality.

What I have noticed right away though, 1.21.0 is significantly slower at accessing the containers for the first time, and even the account for the first time on opening Storage Explorer. When I double click on a container to view the contents, there is over 14 seconds between when I clicked, and it opening. Possible worse is that there is no feedback in the UI that the request has been acknowledged and it is attempting to open the container. Navigating directories once the container is open is fine. As is closing the container and re-opening the container.

[skywalkerisnull]

@MRayermannMSFT I have setup the local Azure Blob IoT and can confirm that I can delete blobs even without the *.blob. domain name (i.e. connecting to localhost). I did also observe the same large latency when connecting to this IoT blob instance even when it is on the same machine.

[MRayermannMSFT]

@skywalkerisnull huh, that's definitely not expected. Can you gather and share your Storage Explorer logs with us? Also if you're able to post a screen or gif recording of what you are visually seeing that would be super helpful as well.

@JasonYeMSFT let's try to figure out what is going on here.

[skywalkerisnull]

Hello @MRayermannMSFT.

Here are the logs: logs.zip

Video of what is happening: https://youtu.be/_1tGr5P_c_A

This repo may help you more quickly test against the Azure IoT Blob instead of setting up an entire environment: https://github.com/skywalkerisnull/azure-blob-iot

[JasonYeMSFT]

In our shared blob container code, we make API call to getAccountInfo to get necessary information before loading the node or opening the container.

The IoT Edge based blob service takes a significant long time to process the request and returns a 500 internal error. Even though it is listed as an unsupported API, I would expect it to fail immediately with some reasonable error instead of such an internal error.

There is a workaround for you to access this type of resource without such delays. In Storage Explorer, you can toggle the Azure Stack option (App Menu > Edit > Target Azure Stack API) to force using API at version 2017-04-17. According to IoT Edge documentation, it happens to be the API version that it is consistent to at the moment IoT Edge supported APIs. When the API version is set, the same request won't trigger the problematic code path on the server and fail immediately.

[skywalkerisnull]

@JasonYeMSFT enabling "Target Azure Stack API" does make it significantly faster to access.

[JasonYeMSFT]

Let's close this issue as mitigated. We should notify the service team to protect unsupported APIs.