search

Azure / Azurite

A lightweight server clone of Azure Storage that simulates most of the commands supported by it with minimal dependencies
MIT License
1.74k stars 309 forks source link

3.30.0 - StartCopyFromUriAsync - 500 Error #2392

Open AshleyMedway opened 2 months ago

AshleyMedway commented 2 months ago

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

blueww commented 2 months ago

@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

SamarthMayya commented 1 month ago

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"}

blueww commented 1 month ago

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?

EmmaZhu commented 1 month ago

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)

SamarthMayya commented 1 month ago

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 commented 1 month ago

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.

44dw commented 1 month ago

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.