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.82k stars 322 forks source link

unable to create blob: Server failed to authenticate request #629

Open iliuta opened 3 years ago

iliuta commented 3 years ago

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

blob

Which version of the Azurite was used?

3.9.0

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

DockerHub

What problem was encountered?

 22:01:12.967 INFO  STDOUT: 172.17.0.1 - - [16/Nov/2020:22:01:12 +0000] "GET /devstoreaccount1/dbvvehiclefiles?restype=container HTTP/1.1" 404 -
    22:01:12.984 INFO  STDOUT: 172.17.0.1 - - [16/Nov/2020:22:01:12 +0000] "PUT /devstoreaccount1/dbvvehiclefiles?restype=container HTTP/1.1" 201 -
    22:01:12.998 INFO  STDOUT: 172.17.0.1 - - [16/Nov/2020:22:01:12 +0000] "HEAD /devstoreaccount1/dbvvehiclefiles/vnext-202011161001129.xml HTTP/1.1" 404 -
    22:01:13.034 INFO  STDOUT: 172.17.0.1 - - [16/Nov/2020:22:01:13 +0000] "PUT /devstoreaccount1/dbvvehiclefiles/vnext-202011161001129.xml HTTP/1.1" 403

...

Caused by: com.azure.storage.blob.models.BlobStorageException: Status code 403, "<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
    <Error>
      <Code>AuthorizationFailure</Code>
      <Message>Server failed to authenticate the request. Make sure the value of the Authorization header is formed correctly including the signature.
    RequestId:0b02a5b3-f84b-4ca0-92c2-164bb75213e2
    Time:2020-11-16T22:01:13.032Z</Message>
    </Error>

As you can see, I am able to create a container but I am not able to write to the blob in the previously created container.

Later in my tests, I am able to do some cleanups:

 22:01:13.076 INFO  STDOUT: 172.17.0.1 - - [16/Nov/2020:22:01:13 +0000] "GET /devstoreaccount1/dbvvehiclefiles?restype=container HTTP/1.1" 200 -
    22:01:13.098 INFO  STDOUT: 172.17.0.1 - - [16/Nov/2020:22:01:13 +0000] "DELETE /devstoreaccount1/dbvvehiclefiles?restype=container HTTP/1.1" 202 -

Since some operations are working, I infer that the credentials are transmitted well into the request.

Steps to reproduce the issue?

I'm trying to use Azurite with the Java SDK in order to run some integration tests with docker and testcontainers java library. Those tests are running just fine on the local machine but, as soon as I execute them in the CI environment (gitlab), I run into "AuthorizationFailure".

The only difference I can see is that in CI environment I have a proxy configuration.

I'm not able to get the error logs from the Azurite server as it runs in a Docker container on the CI platform and it is destroyed right after the pipeline fails. So, if you can suggest a method to bring them up to the console, I would be happy to implement it.

Have you found a mitigation/solution?

No

Any ideas about what's going wrong?

Thanks.

iliuta commented 3 years ago

Hi, I finally managed to have debug logs, by redrecting them to /dev/stdout:

07:58:10.786 DEBUG [id: 0xbcb9cfad, L:/172.17.0.2:60082 - R:172.17.0.1/172.17.0.1:32771] Handler is being applied: {uri=http://172.17.0.1:32771/devstoreaccount1/dbvvehiclefiles/vnext-202011170758105.xml, method=PUT}
    07:58:10.808 INFO  STDOUT: 2020-11-17T07:58:10.800Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://172.17.0.1/devstoreaccount1/dbvvehiclefiles/vnext-202011170758105.xml RequestHeaders:{"accept":"*/*","authorization":"SharedKey devstoreaccount1:SNDVjYjvIpfbj8DtxNgEnp9EKkXDnZU/v9MoO7wXlQk=","content-length":"3582","content-type":"application/octet-stream","cookie":"dtCookie=v_4_srv_28_sn_D7300F7C4C5A54A6646B4B5862C2A790_perc_100000_ol_0_mul_1","date":"Tue, 17 Nov 2020 07:58:10 GMT","host":"172.17.0.1:32771","user-agent":"azsdk-java-azure-storage-blob/12.8.0 (11.0.9; Linux; 4.14.104-95.84.amzn2.x86_64)","x-dynatrace-application":"1%3B1%3Bea7c4b59f27d43eb","x-dynatrace-origin-url":"http://172.17.0.1:32771/devstoreaccount1/dbvvehiclefiles/vnext-202011170758105.xml","x-ms-blob-type":"BlockBlob","x-ms-client-request-id":"94a5b3f7-7581-459d-8bd7-0931f0c40a14","x-ms-version":"2019-12-12"} ClientIP=172.17.0.1 Protocol=http HTTPVersion=1.1
    07:58:10.830 INFO  STDOUT: 172.17.0.1 - - [17/Nov/2020:07:58:10 +0000] "PUT /devstoreaccount1/dbvvehiclefiles/vnext-202011170758105.xml HTTP/1.1" 403 -
    07:58:10.831 INFO  STDOUT: 2020-11-17T07:58:10.801Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=dbvvehiclefiles Blob=vnext-202011170758105.xml
    07:58:10.832 INFO  STDOUT: 2020-11-17T07:58:10.801Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d verbose: DispatchMiddleware: Dispatching request...
    07:58:10.833 INFO  STDOUT: 2020-11-17T07:58:10.804Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: DispatchMiddleware: Operation=BlockBlob_Upload
    07:58:10.833 INFO  STDOUT: 2020-11-17T07:58:10.804Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
    07:58:10.834 INFO  STDOUT: 2020-11-17T07:58:10.804Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: PublicAccessAuthenticator:validate() Start validation against public access.
    07:58:10.834 INFO  STDOUT: 2020-11-17T07:58:10.805Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: PublicAccessAuthenticator:validate() Getting account properties...
    07:58:10.835 INFO  STDOUT: 2020-11-17T07:58:10.805Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: dbvvehiclefiles, blob: vnext-202011170758105.xml
    07:58:10.837 INFO  STDOUT: 2020-11-17T07:58:10.805Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container dbvvehiclefiles
    07:58:10.838 INFO  STDOUT: 2020-11-17T07:58:10.806Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
    07:58:10.839 INFO  STDOUT: 2020-11-17T07:58:10.806Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n3582\n\napplication/octet-stream\nTue, 17 Nov 2020 07:58:10 GMT\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-client-request-id:94a5b3f7-7581-459d-8bd7-0931f0c40a14\nx-ms-version:2019-12-12\n/devstoreaccount1/devstoreaccount1/dbvvehiclefiles/vnext-202011170758105.xml"
    07:58:10.841 INFO  STDOUT: 2020-11-17T07:58:10.806Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:MJUppTE3FiRI3bBDQZz5Appvfv9mLgKcemVE0OKWCF4=
    07:58:10.841 INFO  STDOUT: 2020-11-17T07:58:10.806Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: BlobSharedKeyAuthenticator:validate() Validation failed.
    07:58:10.842 INFO  STDOUT: 2020-11-17T07:58:10.807Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: AccountSASAuthenticator:validate() Start validation against account Shared Access Signature pattern.
    07:58:10.843 INFO  STDOUT: 2020-11-17T07:58:10.807Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: AccountSASAuthenticator:validate() Getting account properties...
    07:58:10.843 INFO  STDOUT: 2020-11-17T07:58:10.807Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: AccountSASAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: dbvvehiclefiles, blob: vnext-202011170758105.xml
    07:58:10.844 INFO  STDOUT: 2020-11-17T07:58:10.807Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: AccountSASAuthenticator:validate() Got account properties successfully.
    07:58:10.844 INFO  STDOUT: 2020-11-17T07:58:10.807Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: AccountSASAuthenticator:validate() Retrieved signature from URL parameter sig: undefined
    07:58:10.845 INFO  STDOUT: 2020-11-17T07:58:10.807Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: AccountSASAuthenticator:validate() Failed to get valid account SAS values from request.
    07:58:10.845 INFO  STDOUT: 2020-11-17T07:58:10.810Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: BlobSASAuthenticator:validate() Start validation against blob service Shared Access Signature pattern.
    07:58:10.846 INFO  STDOUT: 2020-11-17T07:58:10.821Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: BlobSASAuthenticator:validate() Getting account properties...
    07:58:10.846 INFO  STDOUT: 2020-11-17T07:58:10.821Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: BlobSASAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: dbvvehiclefiles, blob: vnext-202011170758105.xml
    07:58:10.847 INFO  STDOUT: 2020-11-17T07:58:10.821Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: BlobSASAuthenticator:validate() Got account properties successfully.
    07:58:10.847 INFO  STDOUT: 2020-11-17T07:58:10.821Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: BlobSASAuthenticator:validate() Retrieved signature from URL parameter sig: undefined
    07:58:10.848 INFO  STDOUT: 2020-11-17T07:58:10.821Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d debug: BlobSASAuthenticator:validate() No signature found in request. Skip blob service SAS validation.
    07:58:10.848 INFO  STDOUT: 2020-11-17T07:58:10.822Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d error: ErrorMiddleware: Received a MiddlewareError, fill error information to HTTP response
    07:58:10.849 INFO  STDOUT: 2020-11-17T07:58:10.822Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d error: ErrorMiddleware: ErrorName=StorageError ErrorMessage=Server failed to authenticate the request. Make sure the value of the Authorization header is formed correctly including the signature.  ErrorHTTPStatusCode=403 ErrorHTTPStatusMessage=Server failed to authenticate the request. Make sure the value of the Authorization header is formed correctly including the signature. ErrorHTTPHeaders={"x-ms-error-code":"AuthorizationFailure","x-ms-request-id":"c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d"} ErrorHTTPBody="<?xml version=\"1.0\" encoding=\"UTF-8\" standalone=\"yes\"?>\n<Error>\n  <Code>AuthorizationFailure</Code>\n  <Message>Server failed to authenticate the request. Make sure the value of the Authorization header is formed correctly including the signature.\nRequestId:c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d\nTime:2020-11-17T07:58:10.821Z</Message>\n</Error>" ErrorStack="StorageError: Server failed to authenticate the request. Make sure the value of th
    07:58:10.850 INFO  STDOUT: e Authorization header is formed correctly including the signature.\n    at Function.getAuthorizationFailure (/opt/azurite/dist/src/blob/errors/StorageErrorFactory.js:134:16)\n    at /opt/azurite/dist/src/blob/middlewares/AuthenticationMiddlewareFactory.js:22:56\n    at Object.dynatraceOnServiceExecutionIndicator [as doInvoke] (/opt/dynatrace/oneagent/agent/bin/1.203.189.20201030-124742/any/nodejs/nodejsagent.js:1809:20)\n    at Object.b.safeInvoke (/opt/dynatrace/oneagent/agent/bin/1.203.189.20201030-124742/any/nodejs/nodejsagent.js:1860:29)\n    at /opt/dynatrace/oneagent/agent/bin/1.203.189.20201030-124742/any/nodejs/nodejsagent.js:7067:25\n    at processTicksAndRejections (internal/process/task_queues.js:97:5)"
    07:58:10.854 INFO  STDOUT: 2020-11-17T07:58:10.822Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d error: ErrorMiddleware: Set HTTP code: 403
    07:58:10.857 INFO  STDOUT: 2020-11-17T07:58:10.822Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d error: ErrorMiddleware: Set HTTP status message: Server failed to authenticate the request. Make sure the value of the Authorization header is formed correctly including the signature.
    07:58:10.857 INFO  STDOUT: 2020-11-17T07:58:10.822Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d error: ErrorMiddleware: Set HTTP Header: x-ms-error-code=AuthorizationFailure
    07:58:10.858 INFO  STDOUT: 2020-11-17T07:58:10.822Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d error: ErrorMiddleware: Set HTTP Header: x-ms-request-id=c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d
    07:58:10.858 INFO  STDOUT: 2020-11-17T07:58:10.822Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d error: ErrorMiddleware: Set content type: application/xml
    07:58:10.859 INFO  STDOUT: 2020-11-17T07:58:10.823Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d error: ErrorMiddleware: Set HTTP body: "<?xml version=\"1.0\" encoding=\"UTF-8\" standalone=\"yes\"?>\n<Error>\n  <Code>AuthorizationFailure</Code>\n  <Message>Server failed to authenticate the request. Make sure the value of the Authorization header is formed correctly including the signature.\nRequestId:c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d\nTime:2020-11-17T07:58:10.821Z</Message>\n</Error>"
    07:58:10.860 INFO  STDOUT: 2020-11-17T07:58:10.823Z c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d info: EndMiddleware: End response. TotalTimeInMS=23 StatusCode=403 StatusMessage=Server failed to authenticate the request. Make sure the value of the Authorization header is formed correctly including the signature. Headers={"server":"Azurite-Blob/3.9.
    07:58:10.860 INFO  STDOUT: 0","x-ms-error-code":"AuthorizationFailure","x-ms-request-id":"c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d","content-type":"application/xml","set-cookie":"dtCookie=v_4_srv_28_sn_D7300F7C4C5A54A6646B4B5862C2A790_perc_100000_ol_0_mul_1; Path=/"}
    07:58:10.913 DEBUG [id: 0xbcb9cfad, L:/172.17.0.2:60082 - R:172.17.0.1/172.17.0.1:32771] Received response (auto-read:false) : [Server=Azurite-Blob/3.9.0, x-ms-error-code=AuthorizationFailure, x-ms-request-id=c2fd4978-eeb7-4ffa-90dd-8a88abdc7c2d, content-type=application/xml, Set-Cookie=dtCookie=v_4_srv_28_sn_D7300F7C4C5A54A6646B4B5862C2A790_perc_100000_ol_0_mul_1; Path=/, Date=Tue, 17 Nov 2020 07:58:10 GMT, Connection=keep-alive, Keep-Alive=timeout=5, Transfer-Encoding=chunked]
iliuta commented 3 years ago

Sorry for the spam, but it looks like in this situation the Java SDK does not produce the same signature for the HTTP call as Azurite.

Java SDK: com.azure.storage.common.StorageSharedKeyCredential#computeHmac256 Azurite: https://github.com/Azure/Azurite/blob/df5bf1dd57162f7722cc861124c9d7c6c9b71352/src/blob/authentication/BlobSharedKeyAuthenticator.ts

Now, where comes from the difference?

XiaoningLiu commented 3 years ago

Hi @iliuta Interesting about "Those tests are running just fine on the local machine but, as soon as I execute them in the CI environment (gitlab), I run into "AuthorizationFailure"."

If that's true, believe the signauture logic between Azurite and Java SDK is same. It sounds like some thing happens on the proxy which changed pieces of the request.

As you can see from the debug log, the string to sign used by Azurite is:

"PUT\n\n\n3582\n\napplication/octet-stream\nTue, 17 Nov 2020 07:58:10 GMT\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-client-request-id:94a5b3f7-7581-459d-8bd7-0931f0c40a14\nx-ms-version:2019-12-12\n/devstoreaccount1/devstoreaccount1/dbvvehiclefiles/vnext-202011170758105.xml"

If you can get string to sign generated by Java SDK then we can easily check the differencies between them.

iliuta commented 3 years ago

Hi @XiaoningLiu, thanks for the response! It's true I have a proxy in CI/CD environment. However, the azurite host is added into nonProxyHosts env variable, therefore the communication is direct. I checked the java source code for generating signature and it seems the same. But, at some moment there is a locale based sorting which I do not see in Azurite side. Tell me if I'm wrong.

I'll try to figure out more on how to log the string sign, but it seems that Azure SDK don't log anything ...

XiaoningLiu commented 3 years ago

Are you referring to sort like this in Azurite https://github.com/Azure/Azurite/blob/df5bf1dd57162f7722cc861124c9d7c6c9b71352/src/blob/authentication/BlobSharedKeyAuthenticator.ts#L191 ?

iliuta commented 3 years ago

Thanks, it looks like. I haven't seen it before.

On the java side there is this method:

    private String getAdditionalXmsHeaders(Map<String, String> headers) {
        // Add only headers that begin with 'x-ms-'
        final List<String> xmsHeaderNameArray = headers.entrySet().stream()
            .filter(entry -> entry.getKey().toLowerCase(Locale.ROOT).startsWith("x-ms-"))
            .filter(entry -> entry.getValue() != null)
            .map(Map.Entry::getKey)
            .collect(Collectors.toList());

        if (xmsHeaderNameArray.isEmpty()) {
            return "";
        }

        /* Culture-sensitive word sort */
        Collections.sort(xmsHeaderNameArray, Collator.getInstance(Locale.ROOT));

        final StringBuilder canonicalizedHeaders = new StringBuilder();
        for (final String key : xmsHeaderNameArray) {
            if (canonicalizedHeaders.length() > 0) {
                canonicalizedHeaders.append('\n');
            }

            canonicalizedHeaders.append(key.toLowerCase(Locale.ROOT))
                .append(':')
                .append(headers.get(key));
        }

        return canonicalizedHeaders.toString();
    }

I can't figure why the result is different. The headers look the same on both sides ...

XiaoningLiu commented 3 years ago

Can you try to print out the Java SDK's string to sign? As Java SDK is open source, believe you can modify their code for the print out if Java SDK doesn't have default logging for that.

c-w commented 3 years ago

I'm also running into this problem when sending a request to AzuriteV3 that sets a Content-Encoding header using libcloud.

According to the SharedKey authorization documentation, the signature should put first the content-encoding and then the content-language:

Screenshot of shared key signature documentation

However, AzuriteV3 builds the signature by first putting the content-language and then the content-encoding:

https://github.com/Azure/Azurite/blob/de832c45ef5be29324f640e3921311ea522980ae/src/blob/authentication/BlobSharedKeyAuthenticator.ts#L55-L56

When I modify libcloud's signature generation code to flip the order of content-encoding and content-language, authentication succeeds against AzuriteV3 but fails against a cloud StorageV2 account which makes me hypothesize that AzuriteV3's implementation here may be incorrect?

Note that this issue currently can't be reproduced using the Javascript Azure Storage SDK as it contains the same flipped logic to compute the authorization header. The Python Azure Storage SDK on the other hand implements the headers in the order described by the documentation, as does the Java SDK.

I'm happy to open a pull request to fix this issue if desired.

ArtemTrofimushkin commented 3 years ago

Hi, @XiaoningLiu I'm also running into this issue, when sending requests to AzuriteV3 (3.11) (for integration testing). I'm using azure SDK for Rust and here is sources: old sdk, new sdk) As mentioned earlier by @c-w, the authorization problem may be in Azurite source code, in this lines. When I clone Azurite source-code, flip lines, rebuild and run docker image, the mentioned problem was gone. So, what needs to be done to fix this issue?

ArtemTrofimushkin commented 3 years ago

Hi, @XiaoningLiu I opened pull request for this

stale[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.