Azurite icon indicating copy to clipboard operation
Azurite copied to clipboard

Published 20 hours ago • verified publisher icon Azure

3.30.0 - StartCopyFromUriAsync - 500 Error

Open AshleyMedway opened this issue 10 months ago • 9 comments

Which service(blob, file, queue, table) does this issue concern?

blob

Which version of the Azurite was used?

3.30.0

Where do you get Azurite? (npm, DockerHub, NuGet, Visual Studio Code Extension)

docker

What's the Node.js version?

N/A

What problem was encountered?

Error Message:
   Azure.RequestFailedException : Service request failed.
Status: 500 (Internal Server Error)

Headers:
Server: Azurite-Blob/3.30.0
Date: Fri, 26 Apr 2024 10:04:24 GMT
Connection: keep-alive
Keep-Alive: REDACTED
Content-Length: 0

Stack Trace:
   at Azure.Storage.Blobs.BlobRestClient.StartCopyFromURLAsync(String copySource, Nullable`1 timeout, IDictionary`2 metadata, Nullable`1 tier, Nullable`1 rehydratePriority, Nullable`1 sourceIfModifiedSince, Nullable`1 sourceIfUnmodifiedSince, String sourceIfMatch, String sourceIfNoneMatch, String sourceIfTags, Nullable`1 ifModifiedSince, Nullable`1 ifUnmodifiedSince, String ifMatch, String ifNoneMatch, String ifTags, String leaseId, String blobTagsString, Nullable`1 sealBlob, Nullable`1 immutabilityPolicyExpiry, Nullable`1 immutabilityPolicyMode, Nullable`1 legalHold, CancellationToken cancellationToken)
   at Azure.Storage.Blobs.Specialized.BlobBaseClient.StartCopyFromUriInternal(Uri source, IDictionary`2 metadata, IDictionary`2 tags, Nullable`1 accessTier, BlobRequestConditions sourceConditions, BlobRequestConditions destinationConditions, Nullable`1 rehydratePriority, Nullable`1 sealBlob, BlobImmutabilityPolicy destinationImmutabilityPolicy, Nullable`1 legalHold, Boolean async, CancellationToken cancellationToken)
   at Azure.Storage.Blobs.Specialized.BlobBaseClient.StartCopyFromUriAsync(Uri source, BlobCopyFromUriOptions options, CancellationToken cancellationToken)

Steps to reproduce the issue?

Our test creates two containers, uploads an image to one container then tries to copy by url with sas token.

var blobService = new BlobServiceClient(connectionString);

var a = blobService.GetBlobContainerClient("container-a");
await a.CreateIfNotExistsAsync();

var b = blobService.GetBlobContainerClient("container-b");
await b.CreateIfNotExistsAsync();

var blob = a.GetBlobClient("Test1/Test2/Example.png");

const string base64Image = "iVBORw0KGgoAAAANSUhEUgAAACAAAAAgCAIAAAD8GO2jAAAARUlEQVR4nGJxk6tkIAUwFcSSpp4k1WSAUQtGLRi1YNSCUQuoAViqbmiTpOE2vwRJ6od+EI1aMGrBqAWjFowICwABAAD//8sqBHDcliZLAAAAAElFTkSuQmCC";
using (var ms = new MemoryStream(Convert.FromBase64String(base64Image)))
{
    await blob.UploadAsync(ms, new BlobHttpHeaders
    {
        ContentType = "image/png"
    });
}

var sasCredential = new StorageSharedKeyCredential("AccountNameFromConnectionString", "AccountKeyFromConnectionString");
var blockBlob = new BlockBlobClient(blob.Uri, sasCredential);

var policy = new BlobSasBuilder(BlobSasPermissions.Read, DateTimeOffset.UtcNow.AddMinutes(5))
{
    StartsOn = DateTimeOffset.UtcNow
};

var sasUri = blockBlob.GenerateSasUri(policy);

var bBlobClient = b.GetBlobClient("Test3/Example.png");
var blobProperties = await blockBlob.GetPropertiesAsync();

var options = new BlobCopyFromUriOptions
{
    DestinationConditions = new BlobRequestConditions { IfModifiedSince = null }
};
var copyOperation = await bBlobClient.StartCopyFromUriAsync(sasUri, options); // <--- Error here
await copyOperation.WaitForCompletionAsync();

Have you found a mitigation/solution?

Downgrade to 3.29.0

AshleyMedway avatar Apr 26 '24 10:04 AshleyMedway

@AshleyMedway

I can't repro this problem with above test code and Azurite docker image 3.30.0 on my local test machine. Would you please share the Azurite debug log of the failed request for investigation?

BTW, we do add more source SAS permission checking on blob copy in 3.30.0, with PR https://github.com/Azure/Azurite/pull/2330

blueww avatar Apr 29 '24 03:04 blueww

I'm facing the same issue too. In my case, I faced this issue with HTTPS setup of Azurite. (creating and installing self-signed certificates using openssl). Below are the debug logs for this:

2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=https://127.0.0.1/devstoreaccount1/240c8d06-19a5-42cc-bd9f-fa81bfcb208b/destination.txt?sv=2023-11-03&se=2024-05-03T06%3A15%3A26Z&sr=c&sp=rc&sig={redacted} RequestHeaders:{"host":"127.0.0.1:10000","x-ms-copy-source":"https://127.0.0.1:10000/devstoreaccount1/240c8d06-19a5-42cc-bd9f-fa81bfcb208b/source.txt?sv=2023-11-03&se=2024-05-03T06%3A15%3A26Z&sr=c&sp=r&sig={redacted}","x-ms-version":"2023-11-03","accept":"application/xml","x-ms-client-request-id":"8e9ee6ef-a7d3-434f-a376-1914e962e3af","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Blobs/12.19.1 (.NET 6.0.29; Microsoft Windows 10.0.22631)","content-length":"0"} ClientIP=127.0.0.1 Protocol=https HTTPVersion=1.1 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=240c8d06-19a5-42cc-bd9f-fa81bfcb208b Blob=destination.txt 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb verbose: DispatchMiddleware: Dispatching request... 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: DispatchMiddleware: Operation=Blob_StartCopyFromURL 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: PublicAccessAuthenticator:validate() Start validation against public access. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: PublicAccessAuthenticator:validate() Getting account properties... 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: 240c8d06-19a5-42cc-bd9f-fa81bfcb208b, blob: destination.txt 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container 240c8d06-19a5-42cc-bd9f-fa81bfcb208b 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSharedKeyAuthenticator:validate() Request doesn't include valid authentication header. Skip shared key authentication. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: AccountSASAuthenticator:validate() Start validation against account Shared Access Signature pattern. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: AccountSASAuthenticator:validate() Getting account properties... 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: AccountSASAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: 240c8d06-19a5-42cc-bd9f-fa81bfcb208b, blob: destination.txt 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: AccountSASAuthenticator:validate() Got account properties successfully. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: AccountSASAuthenticator:validate() Retrieved signature from URL parameter sig: WrVp7OH5U3jvN1j7gZf1kVazEsb8pJCHLEgwf9yCbU0= 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: AccountSASAuthenticator:validate() Failed to get valid account SAS values from request. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSASAuthenticator:validate() Start validation against blob service Shared Access Signature pattern. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() Getting account properties... 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: 240c8d06-19a5-42cc-bd9f-fa81bfcb208b, blob: destination.txt 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() Got account properties successfully. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() Retrieved signature from URL parameter sig: WrVp7OH5U3jvN1j7gZf1kVazEsb8pJCHLEgwf9yCbU0= 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() Signed resource type is c. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() Successfully got valid blob service SAS values from request. {"version":"2023-11-03","expiryTime":"2024-05-03T06:15:26Z","permissions":"rc","containerName":"240c8d06-19a5-42cc-bd9f-fa81bfcb208b","blobName":"destination.txt","signedResource":"c"} 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSASAuthenticator:validate() Validate signature based account key1. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() String to sign is: "rc\n\n2024-05-03T06:15:26Z\n/blob/devstoreaccount1/240c8d06-19a5-42cc-bd9f-fa81bfcb208b\n\n\n\n2023-11-03\nc\n\n\n\n\n\n\n" 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() Calculated signature is: WrVp7OH5U3jvN1j7gZf1kVazEsb8pJCHLEgwf9yCbU0= 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSASAuthenticator:validate() Signature based on key1 validation passed. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSASAuthenticator:validate() Validate start and expiry time. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSASAuthenticator:validate() Validate IP range. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSASAuthenticator:validate() Validate request protocol. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobSASAuthenticator:validate() Got permission requirements for operation Blob_StartCopyFromURL - {"permission":"wc"} 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSASAuthenticator:validate() For Blob_StartCopyFromURL, if blob exists, the permission must be Write. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: BlobSASAuthenticator:validate() Blob service SAS validation successfully. 2024-05-02T06:15:39.144Z 933256cb-d95d-4f81-8611-90d52f90a8cb verbose: DeserializerMiddleware: Start deserializing... 2024-05-02T06:15:39.145Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{},"requestId":"8e9ee6ef-a7d3-434f-a376-1914e962e3af","sourceModifiedAccessConditions":{},"modifiedAccessConditions":{},"leaseAccessConditions":{}},"copySource":"https://127.0.0.1:10000/devstoreaccount1/240c8d06-19a5-42cc-bd9f-fa81bfcb208b/source.txt?sv=2023-11-03&se=2024-05-03T06%3A15%3A26Z&sr=c&sp=r&sig={redacted}","version":"2023-11-03"} 2024-05-02T06:15:39.145Z 933256cb-d95d-4f81-8611-90d52f90a8cb debug: BlobHandler:startCopyFromURL() Validating access to the source account devstoreaccount1 2024-05-02T06:15:39.149Z 933256cb-d95d-4f81-8611-90d52f90a8cb error: ErrorMiddleware: Received an error, fill error information to HTTP response 2024-05-02T06:15:39.149Z 933256cb-d95d-4f81-8611-90d52f90a8cb error: ErrorMiddleware: ErrorName=Error ErrorMessage=self-signed certificate ErrorStack="Error: self-signed certificate\n at TLSSocket.onConnectSecure (node:_tls_wrap:1674:34)\n at TLSSocket.emit (node:events:518:28)\n at TLSSocket._finishInit (node:_tls_wrap:1085:8)\n at ssl.onhandshakedone (node:_tls_wrap:871:12)" 2024-05-02T06:15:39.149Z 933256cb-d95d-4f81-8611-90d52f90a8cb error: ErrorMiddleware: Set HTTP code: 500 2024-05-02T06:15:39.149Z 933256cb-d95d-4f81-8611-90d52f90a8cb info: EndMiddleware: End response. TotalTimeInMS=5 StatusCode=500 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.30.0"}

SamarthMayya avatar May 02 '24 06:05 SamarthMayya

I can repro this issue with https.

The error report from this code in function validateCopySource(): https://github.com/Azure/Azurite/blob/2bb552e703772b9a57ca713ef271c3c7c624a535/src/blob/handlers/BlobHandler.ts#L735 However, this issue not happen before since copy inside same account won't call this function.

The reason for this failure happen from 3.30.0 is : recent change from https://github.com/Azure/Azurite/pull/2330, which makes even copy inside same account will go through validateCopySource() function. https://github.com/Azure/Azurite/blob/2bb552e703772b9a57ca713ef271c3c7c624a535/src/blob/handlers/BlobHandler.ts#L666

@EmmaZhu Would you please help to look?

blueww avatar May 07 '24 10:05 blueww

Hi @SamarthMayya ,

I think your issue is because it doesn't have write permission for destination. Your destination SAS token only has rc but copy operation would require wc permission:

=[https://127.0.0.1/devstoreaccount1/240c8d06-19a5-42cc-bd9f-fa81bfcb208b/destination.txt?sv=2023-11-03&se=2024-05-03T06%3A15%3A26Z&sr=c&sp=rc&sig=](https://127.0.0.1/devstoreaccount1/240c8d06-19a5-42cc-bd9f-fa81bfcb208b/destination.txt?sv=2023-11-03&se=2024-05-03T06%3A15%3A26Z&sr=c&sp=rc&sig=%7B)

EmmaZhu avatar May 15 '24 06:05 EmmaZhu

Hi @SamarthMayya ,

I think your issue is because it doesn't have write permission for destination. Your destination SAS token only has rc but copy operation would require wc permission:

=[https://127.0.0.1/devstoreaccount1/240c8d06-19a5-42cc-bd9f-fa81bfcb208b/destination.txt?sv=2023-11-03&se=2024-05-03T06%3A15%3A26Z&sr=c&sp=rc&sig=](https://127.0.0.1/devstoreaccount1/240c8d06-19a5-42cc-bd9f-fa81bfcb208b/destination.txt?sv=2023-11-03&se=2024-05-03T06%3A15%3A26Z&sr=c&sp=rc&sig=%7B)

Hi @EmmaZhu, Is this the case even in production storage accounts?

SamarthMayya avatar May 16 '24 03:05 SamarthMayya

https://learn.microsoft.com/en-us/rest/api/storageservices/copy-blob?tabs=shared-access-signatures#account-sas

According to this link, for Copy Blob operation, Write permission isn't necessary: If we want to copy to a new destination blob, Create should be enough.

SamarthMayya avatar May 16 '24 03:05 SamarthMayya

I'm having similar issue, but only in our GitLab pipelines. Here's the stack trace:

2024-05-22T06:02:15.680+0000 [DEBUG] [TestEventLogger]     2024-05-22 09:02:15:679 +0300  WARN 817 --- [ool-38-worker-7] f.r.store.request.StoreClientRequest     : Store client request exception Status code 500, (empty body)
2024-05-22T06:02:15.681+0000 [DEBUG] [TestEventLogger]     2024-05-22 09:02:15:681 +0300  WARN 817 --- [ool-38-worker-7] f.r.store.request.StoreClientRequest     : [FAILED]  StoreClient@AzureBlobStoreAdapter@http://localhost:32769/devstoreaccount1/test-container -> copy file /tmp/test-container2153505541716169122/my_endpoint_test-container/data/input/file1.csv to /tmp/test-container2153505541716169122/my_endpoint_test-container/data/test/file1.csv and took 1102.107602893
2024-05-22T06:02:16.860+0000 [DEBUG] [TestEventLogger]     2024-05-22 09:02:16:860 +0300  WARN 817 --- [eduled-thread-2] f.r.s.r.StoreClientRequestExecutor       : FAILED: StoreClient@AzureBlobStoreAdapter@http://localhost:32769/devstoreaccount1/test-container -> copy file /tmp/test-container2153505541716169122/my_endpoint_test-container/data/input/file1.csv to /tmp/test-container2153505541716169122/my_endpoint_test-container/data/test/file1.csv, going to retry, retries used: 0/1, exception: fi.relex.store.StoreException: : com.azure.storage.blob.models.BlobStorageException: Status code 500, (empty body), 
2024-05-22T06:02:16.860+0000 [DEBUG] [TestEventLogger]         java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:710)
2024-05-22T06:02:16.860+0000 [DEBUG] [TestEventLogger]         com.azure.core.implementation.MethodHandleReflectiveInvoker.invokeWithArguments(MethodHandleReflectiveInvoker.java:35)
2024-05-22T06:02:16.860+0000 [DEBUG] [TestEventLogger]         com.azure.core.implementation.http.rest.ResponseExceptionConstructorCache.invoke(ResponseExceptionConstructorCache.java:51)
2024-05-22T06:02:16.860+0000 [DEBUG] [TestEventLogger]         com.azure.core.implementation.http.rest.RestProxyBase.instantiateUnexpectedException(RestProxyBase.java:356)
2024-05-22T06:02:16.860+0000 [DEBUG] [TestEventLogger]         com.azure.core.implementation.http.rest.AsyncRestProxy.lambda$ensureExpectedStatus$1(AsyncRestProxy.java:128)

When I run the same test locally, all goes well. Downgrade to 3.29.0 solves the problem.

44dw avatar May 24 '24 06:05 44dw

What's the status of that issue? I cannot use the newest Azure.Storage.Blobs (version 12.22.1) which requires Blob API version 2024-11-04 introduced in version 3.32.0. I don't want to downgrade to pre 3.30.0, as I will need to downgrade Azure.Storage.Blobs, Microsoft.Azure.WebJobs.Extensions.Storage.Blobs, etc. It's just too much of a hassle. Please fix this issue.

michalchecinski avatar Sep 26 '24 21:09 michalchecinski

What's the status of that issue? I cannot use the newest Azure.Storage.Blobs (version 12.22.1) which requires Blob API version 2024-11-04 introduced in version 3.32.0. I don't want to downgrade to pre 3.30.0, as I will need to downgrade Azure.Storage.Blobs, Microsoft.Azure.WebJobs.Extensions.Storage.Blobs, etc. It's just too much of a hassle. Please fix this issue.

@michalchecinski Would you please share the Azurite debug log, so we can identify if it's the same issue? Besides that, if you downgrade to Azurite 3.29.0, you can start Azurite with "--skipApiVersionCheck", then you don't need downgrade the SDK version.

blueww avatar Sep 27 '24 02:09 blueww