3.30.0 - StartCopyFromUriAsync - 500 Error about azurite HOT 7 OPEN

@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

from azurite.

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

from azurite.

I can repro this issue with https.

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

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.

@EmmaZhu Would you please help to look?

from azurite.

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)

from azurite.

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?

from azurite.

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.

from azurite.

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.

from azurite.