Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

3.30.0 - StartCopyFromUriAsync - 500 Error #2392

Open
AshleyMedway opened this issue Apr 26, 2024 · 7 comments
Open

3.30.0 - StartCopyFromUriAsync - 500 Error #2392

AshleyMedway opened this issue Apr 26, 2024 · 7 comments
Assignees
@EmmaZhu @blueww
Labels
blob-storage question Further information is requested

Comments

@AshleyMedway
Copy link

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 AshleyMedway changed the title 3.33.0 - StartCopyFromUriAsync - 500 Error 3.30.0 - StartCopyFromUriAsync - 500 Error Apr 26, 2024
@blueww blueww self-assigned this Apr 29, 2024
@blueww blueww added question Further information is requested blob-storage labels Apr 29, 2024
@blueww
Copy link
Member

blueww commented Apr 29, 2024 •
edited

@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 #2330

@SamarthMayya
Copy link

SamarthMayya commented May 2, 2024 •
edited

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
Copy link
Member

blueww commented May 7, 2024 •
edited

I can repro this issue with https.

The error report from this code in function validateCopySource():

Azurite/src/blob/handlers/BlobHandler.ts

Line 735 in 2bb552e

const validationResponse: AxiosResponse = await axios.get(

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 #2330, which makes even copy inside same account will go through validateCopySource() function.

Azurite/src/blob/handlers/BlobHandler.ts

Line 666 in 2bb552e

if ((sourceAccount !== blobCtx.account) || (sig !== null)) {

@EmmaZhu Would you please help to look?

@EmmaZhu
Copy link
Collaborator

EmmaZhu commented May 15, 2024 •
edited

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
Copy link

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
Copy link

SamarthMayya commented May 16, 2024 •
edited

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
Copy link

44dw commented May 24, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@EmmaZhu EmmaZhu

@blueww blueww

Labels
blob-storage question Further information is requested
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@AshleyMedway @EmmaZhu @blueww @44dw @SamarthMayya