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.83k stars 325 forks source link

Azurite truncates blob if Content-Length: 0 header is added with metadata updates, but Azure blob does not truncate #1668

Open nitinkgupta opened 2 years ago

nitinkgupta commented 2 years ago

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

block blob

Which version of the Azurite was used?

mcr.microsoft.com/azure-storage/azurite

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

mcr.microsoft.com/azure-storage/azurite

What's the Node.js version?

N/A

What problem was encountered?

Blob REST API requires a Content-Length header be provided for metadata updates even though the documentation doesn't mention it: https://docs.microsoft.com/en-us/rest/api/storageservices/set-blob-metadata If we provide Content-Length = 0 to blob, the put metadata call succeeds without any issues and the blob shows the new metadata with its contents intact.

With Azurite, the same call with Content-Length = 0, results in the blob getting truncated to 0 length.

Also, note that the Content-Length header is required when sending the request to Azure block blob. However, the Content-Length header can be skipped when sending the request to Azurite. If the Content-Length header is skipped, Azurite correctly updates the metadata without truncating the underlying blob.

Steps to reproduce the issue?

If possible, please provide the debug log using the -d parameter, replacing \<pathtodebuglog> with an appropriate path for your OS, or review the instructions for docker containers:

-d "<pathtodebuglog>"

Please be sure to remove any PII or sensitive information before sharing!
The debug log will log raw request headers and bodies, so that we can replay these against Azurite using REST and create tests to validate resolution.

Have you found a mitigation/solution?

The current mitigation is to skip the Content-Length header when sending the request to Azurite, but providing the header with 0 value when talking to blob.

blueww commented 2 years ago

@nitinkgupta

I can't repro this issue with latest Azurite on my machine. In my test, I send a set metadata request to Azurite with "content-length":"0", then send a get blob properties request to azurite, Azurite returned blob properties still has "content-length":"10485760", it doesn't truncated to 0 length.

Following is the Azurite debug from my test.

Would you please attach the Azurite debug log from you side which can repro this issue? Please include the set metadata API and a following API which can show the blob is truncated to 0 length.

2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/sparkconnectortests1/test.txt?comp=metadata RequestHeaders:{"x-ms-meta-tag2":"value22","x-ms-meta-tag1":"value1","x-ms-meta-tag3":"va4","x-ms-client-request-id":"12b956c0-e856-4370-b9a1-3c1cd78fd387","user-agent":"Azure-Storage/11.2.2 (.NET Core; Win32NT 10.0.19044.0)","x-ms-version":"2019-07-07","x-ms-date":"Wed, 07 Sep 2022 06:04:18 GMT","authorization":"SharedKey devstoreaccount1:6YP1G7tvfxoJVbYK9n0v8f9Oisv9z8anXpxsLI0RUCY=","host":"127.0.0.1:10000","content-length":"0"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info BlobStorageContextMiddleware: Account=devstoreaccount1 Container=sparkconnectortests1 Blob=test.txt
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 verbose DispatchMiddleware: Dispatching request...
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info DispatchMiddleware: Operation=Blob_SetMetadata
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 verbose AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 debug PublicAccessAuthenticator:validate() Getting account properties...
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 debug PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: sparkconnectortests1, blob: test.txt
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 debug PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container sparkconnectortests1
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-07T06:04:18.630Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:12b956c0-e856-4370-b9a1-3c1cd78fd387\nx-ms-date:Wed, 07 Sep 2022 06:04:18 GMT\nx-ms-meta-tag1:value1\nx-ms-meta-tag2:value22\nx-ms-meta-tag3:va4\nx-ms-version:2019-07-07\n/devstoreaccount1/devstoreaccount1/sparkconnectortests1/test.txt\ncomp:metadata"
2022-09-07T06:04:18.631Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:6YP1G7tvfxoJVbYK9n0v8f9Oisv9z8anXpxsLI0RUCY=
2022-09-07T06:04:18.631Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-07T06:04:18.631Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 verbose DeserializerMiddleware: Start deserializing...
2022-09-07T06:04:18.631Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info HandlerMiddleware: DeserializedParameters={"options":{"metadata":{"tag2":"value22","tag1":"value1","tag3":"va4"},"requestId":"12b956c0-e856-4370-b9a1-3c1cd78fd387","leaseAccessConditions":{},"cpkInfo":{},"modifiedAccessConditions":{}},"comp":"metadata","version":"2019-07-07"}
2022-09-07T06:04:18.631Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 verbose SerializerMiddleware: Start serializing...
2022-09-07T06:04:18.631Z 80368ea4-c4e8-4481-a6cd-a1d738e2e9b0 info EndMiddleware: End response. TotalTimeInMS=1 StatusCode=200 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","etag":"\"0x215D43CF8FA7660\"","last-modified":"Wed, 07 Sep 2022 06:04:18 GMT","x-ms-client-request-id":"12b956c0-e856-4370-b9a1-3c1cd78fd387","x-ms-request-id":"80368ea4-c4e8-4481-a6cd-a1d738e2e9b0","x-ms-version":"2021-10-04","date":"Wed, 07 Sep 2022 06:04:18 GMT","x-ms-request-server-encrypted":"true"}
2022-09-07T06:04:20.298Z     info AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2022-09-07T06:04:20.298Z     info AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info BlobStorageContextMiddleware: RequestMethod=HEAD RequestURL=http://127.0.0.1/devstoreaccount1/sparkconnectortests1/test.txt RequestHeaders:{"x-ms-version":"2021-06-08","accept":"application/xml","user-agent":"AzurePowershell/v1.0.0,azsdk-net-Storage.Blobs/12.12.0 (.NET Framework 4.8.4510.0; Microsoft Windows 10.0.19044 )","x-ms-client-request-id":"d2768f60-d477-4e2c-9493-ab53d82d3984","x-ms-return-client-request-id":"true","x-ms-date":"Wed, 07 Sep 2022 06:04:30 GMT","authorization":"SharedKey devstoreaccount1:Xi9hojs2Zhw0GTTQFgMFHsVIzUBa7nKE2WTlaPUtbnU=","host":"127.0.0.1:10000"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info BlobStorageContextMiddleware: Account=devstoreaccount1 Container=sparkconnectortests1 Blob=test.txt
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b verbose DispatchMiddleware: Dispatching request...
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info DispatchMiddleware: Operation=Blob_GetProperties
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b verbose AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b debug PublicAccessAuthenticator:validate() Getting account properties...
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b debug PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: sparkconnectortests1, blob: test.txt
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b debug PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container sparkconnectortests1
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-07T06:04:30.516Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"HEAD\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:d2768f60-d477-4e2c-9493-ab53d82d3984\nx-ms-date:Wed, 07 Sep 2022 06:04:30 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2021-06-08\n/devstoreaccount1/devstoreaccount1/sparkconnectortests1/test.txt"
2022-09-07T06:04:30.517Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:Xi9hojs2Zhw0GTTQFgMFHsVIzUBa7nKE2WTlaPUtbnU=
2022-09-07T06:04:30.517Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-07T06:04:30.517Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b verbose DeserializerMiddleware: Start deserializing...
2022-09-07T06:04:30.517Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info HandlerMiddleware: DeserializedParameters={"options":{"requestId":"d2768f60-d477-4e2c-9493-ab53d82d3984","leaseAccessConditions":{},"cpkInfo":{},"modifiedAccessConditions":{}},"version":"2021-06-08"}
2022-09-07T06:04:30.517Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b verbose SerializerMiddleware: Start serializing...
2022-09-07T06:04:30.517Z 7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b info EndMiddleware: End response. TotalTimeInMS=1 StatusCode=200 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","last-modified":"Wed, 07 Sep 2022 06:04:18 GMT","x-ms-creation-time":"Wed, 07 Sep 2022 06:03:39 GMT","x-ms-meta-tag2":"value22","x-ms-meta-tag1":"value1","x-ms-meta-tag3":"va4","x-ms-blob-type":"BlockBlob","x-ms-lease-state":"available","x-ms-lease-status":"unlocked","content-length":"10485760","content-type":"image/jpeg","etag":"\"0x215D43CF8FA7660\"","content-md5":"i727sP7HigloQDsqadNLHw==","x-ms-client-request-id":"d2768f60-d477-4e2c-9493-ab53d82d3984","x-ms-request-id":"7b85cd76-e39b-43d6-8c4a-cd0fc13deb6b","x-ms-version":"2021-10-04","date":"Wed, 07 Sep 2022 06:04:30 GMT","accept-ranges":"bytes","x-ms-server-encrypted":"true","x-ms-access-tier":"Hot","x-ms-access-tier-inferred":"true"}
blueww commented 2 years ago

@nitinkgupta

Do you have any update on this?

nitinkgupta commented 2 years ago

@blueww

Sorry for the delay in responding. I'm attaching the azurite debug log. Our test creates a blob with two blocks. then commits the blocklist, then updates attributes. After that we get an empty blocklist and see the blob has truncated to size 0:

2022-09-15T14:20:13.748Z         info: Azurite Blob service is starting on 0.0.0.0:10000
2022-09-15T14:20:13.754Z         info: AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2022-09-15T14:20:13.755Z         info: AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2022-09-15T14:20:13.822Z         info: BlobGCManager:start() Starting BlobGCManager. Set status to Initializing.
2022-09-15T14:20:13.822Z         info: BlobGCManager:start() Trigger mark and sweep loop. Set status to Running.
2022-09-15T14:20:13.822Z         info: BlobGCManager:markSweepLoop() Start next mark and sweep.
2022-09-15T14:20:13.823Z         info: BlobGCManager:markSweep() Get all extents.
2022-09-15T14:20:13.824Z         info: BlobGCManager:start() BlobGCManager successfully started.
2022-09-15T14:20:13.826Z         info: BlobGCManager:markSweep() Got 0 extents.
2022-09-15T14:20:13.826Z         info: BlobGCManager:markSweep() Get referred extents.
2022-09-15T14:20:13.827Z         info: BlobGCManager:markSweep() Got referred extents, unreferenced extents count is 0.
2022-09-15T14:20:13.828Z         info: BlobGCManager:markSweepLoop() Mark and sweep finished, taken 6ms.
2022-09-15T14:20:13.828Z         info: BlobGCManager:markSweepLoop() Sleep for 600000ms.
2022-09-15T14:20:13.831Z         info: Azurite Blob service successfully listens on http://0.0.0.0:10000
2022-09-15T14:20:15.002Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing?restype=container RequestHeaders:{"host":"127.0.0.1:10000","user-agent":"AZURECLI/2.38.0 (HOMEBREW) azsdk-python-storage-blob/12.12.0 Python/3.10.5 (macOS-12.5.1-x86_64-i386-64bit)","accept-encoding":"gzip, deflate","accept":"application/xml","connection":"keep-alive","x-ms-version":"2021-06-08","x-ms-client-request-id":"844fec42-3501-11ed-8df2-acde48001122","commandname":"storage container create","parametersetname":"-n --account-name","x-ms-date":"Thu, 15 Sep 2022 14:20:14 GMT","authorization":"SharedKey devstoreaccount1:kN24jZPBd5o4Y/xPQxlxCC2+UQsOQ9LNwtN9m2amxWg=","content-length":"0"} ClientIP=172.17.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:20:15.005Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=
2022-09-15T14:20:15.006Z bb51c60b-db8a-4c38-821d-1bacf5c06192 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:20:15.011Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: DispatchMiddleware: Operation=Container_Create
2022-09-15T14:20:15.013Z bb51c60b-db8a-4c38-821d-1bacf5c06192 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:20:15.013Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:20:15.013Z bb51c60b-db8a-4c38-821d-1bacf5c06192 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:20:15.013Z bb51c60b-db8a-4c38-821d-1bacf5c06192 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob:
2022-09-15T14:20:15.025Z bb51c60b-db8a-4c38-821d-1bacf5c06192 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:20:15.026Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:20:15.054Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:844fec42-3501-11ed-8df2-acde48001122\nx-ms-date:Thu, 15 Sep 2022 14:20:14 GMT\nx-ms-version:2021-06-08\n/devstoreaccount1/devstoreaccount1/testing\nrestype:container"
2022-09-15T14:20:15.055Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:kN24jZPBd5o4Y/xPQxlxCC2+UQsOQ9LNwtN9m2amxWg=
2022-09-15T14:20:15.055Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:20:15.056Z bb51c60b-db8a-4c38-821d-1bacf5c06192 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:20:15.060Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{},"requestId":"844fec42-3501-11ed-8df2-acde48001122"},"restype":"container","version":"2021-06-08"}
2022-09-15T14:20:15.064Z bb51c60b-db8a-4c38-821d-1bacf5c06192 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:20:15.068Z bb51c60b-db8a-4c38-821d-1bacf5c06192 info: EndMiddleware: End response. TotalTimeInMS=66 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","etag":"\"0x1C93698AC980DF0\"","last-modified":"Thu, 15 Sep 2022 14:20:15 GMT","x-ms-client-request-id":"844fec42-3501-11ed-8df2-acde48001122","x-ms-request-id":"bb51c60b-db8a-4c38-821d-1bacf5c06192","x-ms-version":"2021-10-04"}
2022-09-15T14:20:36.128Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=block&blockid=MSEC00000000 RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-version":"2020-04-08","content-length":"4194304","authorization":"SharedKey devstoreaccount1:lHLiKmQkbCmndDcMtdk4id+Stm/Pf8L2t0a09qLG6TU="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:20:36.129Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:20:36.129Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:20:36.131Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: DispatchMiddleware: Operation=BlockBlob_StageBlock
2022-09-15T14:20:36.131Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:20:36.131Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:20:36.131Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:20:36.131Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:20:36.133Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:20:36.133Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:20:36.133Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n4194304\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:20:36 GMT\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\nblockid:MSEC00000000\ncomp:block"
2022-09-15T14:20:36.134Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:lHLiKmQkbCmndDcMtdk4id+Stm/Pf8L2t0a09qLG6TU=
2022-09-15T14:20:36.134Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:20:36.134Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:20:36.135Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: HandlerMiddleware: DeserializedParameters={"blockId":"MSEC00000000","options":{"leaseAccessConditions":{},"cpkInfo":{}},"comp":"block","contentLength":4194304,"version":"2020-04-08","body":"ReadableStream"}
2022-09-15T14:20:36.136Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue.operate() Schedule incoming job 2c7a1442-634a-438e-8ac7-e6da2c4be8cb
2022-09-15T14:20:36.136Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:1
2022-09-15T14:20:36.137Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:1 extentId:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a offset:0 MAX_EXTENT_SIZE:67108864
2022-09-15T14:20:36.137Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:appendExtent() Get fd:undefined for extent:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a from cache.
2022-09-15T14:20:36.139Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:appendExtent() Open file:/data/__blobstorage__/9e3bd5ad-83d9-424b-b1ec-ced9ad25783a for extent:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a, get new fd:23
2022-09-15T14:20:36.140Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:appendExtent() Created write stream for fd:23
2022-09-15T14:20:36.140Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:appendExtent() Start writing to extent 9e3bd5ad-83d9-424b-b1ec-ced9ad25783a
2022-09-15T14:20:36.140Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:streamPipe() Start piping data to write stream
2022-09-15T14:20:36.224Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:streamPipe() Readable stream triggers close event, 4194304 bytes piped
2022-09-15T14:20:36.224Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:streamPipe() Invoke write stream end()
2022-09-15T14:20:36.228Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:streamPipe() Writable stream triggers finish event, after 4194304 bytes piped. Flush data to fd:23.
2022-09-15T14:20:36.228Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:streamPipe() Flush data to fd:23 successfully. Resolve streamPipe().
2022-09-15T14:20:36.228Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:appendExtent() Write finish, start updating extent metadata. extent:{"id":"9e3bd5ad-83d9-424b-b1ec-ced9ad25783a","locationId":"Default","path":"9e3bd5ad-83d9-424b-b1ec-ced9ad25783a","size":4194304,"lastModifiedInMS":1663251636228}
2022-09-15T14:20:36.229Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:appendExtent() Update extent metadata done. Resolve()
2022-09-15T14:20:36.229Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue.operate() Job 2c7a1442-634a-438e-8ac7-e6da2c4be8cb completes callback, resolve.
2022-09-15T14:20:36.229Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue.operate() Schedule incoming job dfff8c42-fe38-43e5-ad42-5430881ca1e9
2022-09-15T14:20:36.229Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:100 operations.length:1
2022-09-15T14:20:36.229Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 verbose: FSExtentStore:readExtent() Creating read stream. LocationId:Default extentId:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a path:/data/__blobstorage__/9e3bd5ad-83d9-424b-b1ec-ced9ad25783a offset:0 count:4194304 end:4194303
2022-09-15T14:20:36.230Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue.operate() Job dfff8c42-fe38-43e5-ad42-5430881ca1e9 completes callback, resolve.
2022-09-15T14:20:36.230Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:0
2022-09-15T14:20:36.230Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:20:36.230Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:100 operations.length:0
2022-09-15T14:20:36.231Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:20:36.288Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:20:36.289Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 info: EndMiddleware: End response. TotalTimeInMS=161 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","x-ms-request-id":"ebfbb0c5-714b-413e-b9bf-bd21de4a03e9","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-request-server-encrypted":"true"}
2022-09-15T14:20:36.289Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 debug: FSExtentStore:streamPipe() Readable stream triggers close event, 4194304 bytes piped
2022-09-15T14:20:36.290Z ebfbb0c5-714b-413e-b9bf-bd21de4a03e9 verbose: FSExtentStore:readExtent() Read stream closed. LocationId:Default extentId:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a path:/data/__blobstorage__/9e3bd5ad-83d9-424b-b1ec-ced9ad25783a offset:0 count:4194304 end:4194303
2022-09-15T14:20:36.299Z e399bf22-2846-453d-98ac-ab013f976daf info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=block&blockid=MSEC00000001 RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-version":"2020-04-08","content-length":"4194304","authorization":"SharedKey devstoreaccount1:ZyaghmrfzdHtvXt7n/AZ5PCsvYLxT86BVTIXr4304DI="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:20:36.300Z e399bf22-2846-453d-98ac-ab013f976daf info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:20:36.300Z e399bf22-2846-453d-98ac-ab013f976daf verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:20:36.303Z e399bf22-2846-453d-98ac-ab013f976daf info: DispatchMiddleware: Operation=BlockBlob_StageBlock
2022-09-15T14:20:36.304Z e399bf22-2846-453d-98ac-ab013f976daf verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:20:36.304Z e399bf22-2846-453d-98ac-ab013f976daf info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:20:36.304Z e399bf22-2846-453d-98ac-ab013f976daf debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:20:36.304Z e399bf22-2846-453d-98ac-ab013f976daf debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:20:36.304Z e399bf22-2846-453d-98ac-ab013f976daf debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:20:36.304Z e399bf22-2846-453d-98ac-ab013f976daf info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:20:36.305Z e399bf22-2846-453d-98ac-ab013f976daf info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n4194304\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:20:36 GMT\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\nblockid:MSEC00000001\ncomp:block"
2022-09-15T14:20:36.305Z e399bf22-2846-453d-98ac-ab013f976daf info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:ZyaghmrfzdHtvXt7n/AZ5PCsvYLxT86BVTIXr4304DI=
2022-09-15T14:20:36.305Z e399bf22-2846-453d-98ac-ab013f976daf info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:20:36.305Z e399bf22-2846-453d-98ac-ab013f976daf verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:20:36.305Z e399bf22-2846-453d-98ac-ab013f976daf info: HandlerMiddleware: DeserializedParameters={"blockId":"MSEC00000001","options":{"leaseAccessConditions":{},"cpkInfo":{}},"comp":"block","contentLength":4194304,"version":"2020-04-08","body":"ReadableStream"}
2022-09-15T14:20:36.306Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue.operate() Schedule incoming job f0f7c798-b7f2-404a-9609-c5b9c5d416e6
2022-09-15T14:20:36.306Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:1
2022-09-15T14:20:36.306Z e399bf22-2846-453d-98ac-ab013f976daf info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:1 extentId:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a offset:4194304 MAX_EXTENT_SIZE:67108864
2022-09-15T14:20:36.306Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:appendExtent() Get fd:23 for extent:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a from cache.
2022-09-15T14:20:36.306Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:appendExtent() Created write stream for fd:23
2022-09-15T14:20:36.306Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:appendExtent() Start writing to extent 9e3bd5ad-83d9-424b-b1ec-ced9ad25783a
2022-09-15T14:20:36.306Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:streamPipe() Start piping data to write stream
2022-09-15T14:20:36.441Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:streamPipe() Readable stream triggers close event, 4194304 bytes piped
2022-09-15T14:20:36.441Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:streamPipe() Invoke write stream end()
2022-09-15T14:20:36.442Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:streamPipe() Writable stream triggers finish event, after 4194304 bytes piped. Flush data to fd:23.
2022-09-15T14:20:36.442Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:streamPipe() Flush data to fd:23 successfully. Resolve streamPipe().
2022-09-15T14:20:36.442Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:appendExtent() Write finish, start updating extent metadata. extent:{"id":"9e3bd5ad-83d9-424b-b1ec-ced9ad25783a","locationId":"Default","path":"9e3bd5ad-83d9-424b-b1ec-ced9ad25783a","size":8388608,"lastModifiedInMS":1663251636442}
2022-09-15T14:20:36.443Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:appendExtent() Update extent metadata done. Resolve()
2022-09-15T14:20:36.444Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue.operate() Job f0f7c798-b7f2-404a-9609-c5b9c5d416e6 completes callback, resolve.
2022-09-15T14:20:36.444Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue.operate() Schedule incoming job ac6b9401-889b-4e61-8718-25e4dfcd27c1
2022-09-15T14:20:36.444Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:100 operations.length:1
2022-09-15T14:20:36.444Z e399bf22-2846-453d-98ac-ab013f976daf verbose: FSExtentStore:readExtent() Creating read stream. LocationId:Default extentId:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a path:/data/__blobstorage__/9e3bd5ad-83d9-424b-b1ec-ced9ad25783a offset:4194304 count:4194304 end:8388607
2022-09-15T14:20:36.445Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue.operate() Job ac6b9401-889b-4e61-8718-25e4dfcd27c1 completes callback, resolve.
2022-09-15T14:20:36.445Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:0
2022-09-15T14:20:36.445Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:20:36.445Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:100 operations.length:0
2022-09-15T14:20:36.445Z e399bf22-2846-453d-98ac-ab013f976daf debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:20:36.491Z e399bf22-2846-453d-98ac-ab013f976daf verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:20:36.492Z e399bf22-2846-453d-98ac-ab013f976daf info: EndMiddleware: End response. TotalTimeInMS=193 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","x-ms-request-id":"e399bf22-2846-453d-98ac-ab013f976daf","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-request-server-encrypted":"true"}
2022-09-15T14:20:36.492Z e399bf22-2846-453d-98ac-ab013f976daf debug: FSExtentStore:streamPipe() Readable stream triggers close event, 4194304 bytes piped
2022-09-15T14:20:36.493Z e399bf22-2846-453d-98ac-ab013f976daf verbose: FSExtentStore:readExtent() Read stream closed. LocationId:Default extentId:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a path:/data/__blobstorage__/9e3bd5ad-83d9-424b-b1ec-ced9ad25783a offset:4194304 count:4194304 end:8388607
2022-09-15T14:20:36.502Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-version":"2020-04-08","x-ms-meta-edgeattr":"AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==","content-length":"121","authorization":"SharedKey devstoreaccount1:X+O/A6ba7yrrB1qCoz0BRWuL8mHFlNXUkGURRUIP3AE="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:20:36.502Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:20:36.502Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:20:36.509Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: DispatchMiddleware: Operation=BlockBlob_CommitBlockList
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n121\n\ntext/plain\n\n\n\n\n\n\nx-ms-date:Thu, 15 Sep 2022 14:20:36 GMT\nx-ms-meta-edgeattr:AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\ncomp:blocklist"
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:X+O/A6ba7yrrB1qCoz0BRWuL8mHFlNXUkGURRUIP3AE=
2022-09-15T14:20:36.510Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:20:36.511Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:20:36.511Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 debug: deserialize(): Raw request body string is (removed all empty characters) <?xmlversion="1.0"encoding="utf-8"?><BlockList><Latest>MSEC00000000</Latest><Latest>MSEC00000001</Latest></BlockList>
2022-09-15T14:20:36.518Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{"edgeattr":"AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA=="},"blobHTTPHeaders":{},"leaseAccessConditions":{},"cpkInfo":{},"modifiedAccessConditions":{}},"comp":"blocklist","version":"2020-04-08","blocks":{"committed":[],"uncommitted":[],"latest":["MSEC00000000","MSEC00000001"]},"body":"ReadableStream"}
2022-09-15T14:20:36.522Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:20:36.523Z 0cf80840-4087-4b28-b4a7-42d3e5ee5907 info: EndMiddleware: End response. TotalTimeInMS=21 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","etag":"\"0x1C9F0A98AE2C710\"","last-modified":"Thu, 15 Sep 2022 14:20:36 GMT","content-md5":"qS8XBEcWJncimGMJYf6pPg==","x-ms-request-id":"0cf80840-4087-4b28-b4a7-42d3e5ee5907","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-request-server-encrypted":"true"}
2022-09-15T14:20:36.553Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: BlobStorageContextMiddleware: RequestMethod=GET RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-version":"2020-04-08","content-length":"0","authorization":"SharedKey devstoreaccount1:IcqHiYxpxUJCLudd+pIsi3N4ck+dh5z+FUvIKZfVT1o="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:20:36.553Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:20:36.553Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:20:36.554Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: DispatchMiddleware: Operation=BlockBlob_GetBlockList
2022-09-15T14:20:36.554Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:20:36.554Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:20:36.554Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:20:36.554Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:20:36.555Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:20:36.555Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:20:36.555Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"GET\n\n\n\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:20:36 GMT\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\nblocklisttype:all\ncomp:blocklist"
2022-09-15T14:20:36.555Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:IcqHiYxpxUJCLudd+pIsi3N4ck+dh5z+FUvIKZfVT1o=
2022-09-15T14:20:36.555Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:20:36.555Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:20:36.555Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: HandlerMiddleware: DeserializedParameters={"options":{"listType":"all","leaseAccessConditions":{}},"comp":"blocklist","version":"2020-04-08"}
2022-09-15T14:20:36.556Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:20:36.558Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 debug: Serializer: Raw response body string is <?xml version="1.0" encoding="UTF-8" standalone="yes"?><BlockList><CommittedBlocks><Block><Name>MSEC00000000</Name><Size>4194304</Size></Block><Block><Name>MSEC00000001</Name><Size>4194304</Size></Block></CommittedBlocks><UncommittedBlocks/></BlockList>
2022-09-15T14:20:36.558Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: Serializer: Start returning stream body.
2022-09-15T14:20:36.558Z aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119 info: EndMiddleware: End response. TotalTimeInMS=5 StatusCode=200 StatusMessage=OK Headers={"server":"Azurite-Blob/3.19.0","last-modified":"Thu, 15 Sep 2022 14:20:36 GMT","etag":"\"0x1C9F0A98AE2C710\"","content-type":"application/xml","x-ms-blob-content-length":"8388608","x-ms-request-id":"aaed9bb8-9b8e-4e7d-a8a4-c97d23fb5119","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:20:36 GMT"}
2022-09-15T14:20:36.580Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=metadata RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-version":"2020-04-08","x-ms-meta-edgeattr":"AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==","content-length":"0","authorization":"SharedKey devstoreaccount1:k3KlnGgEy35DOca/AtSm8AIcSGrWVYHJgIbus7Waxdg="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:20:36.581Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:20:36.581Z ad4de189-6246-44b5-a401-82b4b33be3f5 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:20:36.584Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: DispatchMiddleware: Operation=BlockBlob_Upload
2022-09-15T14:20:36.584Z ad4de189-6246-44b5-a401-82b4b33be3f5 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:20:36.585Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:20:36.585Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:20:36.585Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:20:36.585Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:20:36.585Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:20:36.586Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:20:36 GMT\nx-ms-meta-edgeattr:AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\ncomp:metadata"
2022-09-15T14:20:36.586Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:k3KlnGgEy35DOca/AtSm8AIcSGrWVYHJgIbus7Waxdg=
2022-09-15T14:20:36.586Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:20:36.586Z ad4de189-6246-44b5-a401-82b4b33be3f5 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:20:36.587Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{"edgeattr":"AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA=="},"blobHTTPHeaders":{},"leaseAccessConditions":{},"cpkInfo":{},"modifiedAccessConditions":{}},"contentLength":0,"version":"2020-04-08","blobType":"BlockBlob","body":"ReadableStream"}
2022-09-15T14:20:36.588Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: OperationQueue.operate() Schedule incoming job 27b9fcae-da94-46b0-90c7-7373759088ba
2022-09-15T14:20:36.588Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:1
2022-09-15T14:20:36.588Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:1 extentId:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a offset:8388608 MAX_EXTENT_SIZE:67108864
2022-09-15T14:20:36.588Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:appendExtent() Get fd:23 for extent:9e3bd5ad-83d9-424b-b1ec-ced9ad25783a from cache.
2022-09-15T14:20:36.588Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:appendExtent() Created write stream for fd:23
2022-09-15T14:20:36.588Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:appendExtent() Start writing to extent 9e3bd5ad-83d9-424b-b1ec-ced9ad25783a
2022-09-15T14:20:36.589Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:streamPipe() Start piping data to write stream
2022-09-15T14:20:36.589Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:streamPipe() Readable stream triggers close event, 0 bytes piped
2022-09-15T14:20:36.589Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:streamPipe() Invoke write stream end()
2022-09-15T14:20:36.589Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:streamPipe() Writable stream triggers finish event, after 0 bytes piped. Flush data to fd:23.
2022-09-15T14:20:36.589Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:streamPipe() Flush data to fd:23 successfully. Resolve streamPipe().
2022-09-15T14:20:36.589Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:appendExtent() Write finish, start updating extent metadata. extent:{"id":"9e3bd5ad-83d9-424b-b1ec-ced9ad25783a","locationId":"Default","path":"9e3bd5ad-83d9-424b-b1ec-ced9ad25783a","size":8388608,"lastModifiedInMS":1663251636589}
2022-09-15T14:20:36.590Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:appendExtent() Update extent metadata done. Resolve()
2022-09-15T14:20:36.590Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: OperationQueue.operate() Job 27b9fcae-da94-46b0-90c7-7373759088ba completes callback, resolve.
2022-09-15T14:20:36.590Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:0
2022-09-15T14:20:36.590Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:20:36.592Z ad4de189-6246-44b5-a401-82b4b33be3f5 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:20:36.592Z ad4de189-6246-44b5-a401-82b4b33be3f5 info: EndMiddleware: End response. TotalTimeInMS=12 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","etag":"\"0x1BC1CE69F718BB0\"","last-modified":"Thu, 15 Sep 2022 14:20:36 GMT","content-md5":"1B2M2Y8AsgTpgAmY7PhCfg==","x-ms-request-id":"ad4de189-6246-44b5-a401-82b4b33be3f5","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-request-server-encrypted":"true"}
2022-09-15T14:20:36.593Z ad4de189-6246-44b5-a401-82b4b33be3f5 debug: FSExtentStore:streamPipe() Readable stream triggers close event, 0 bytes piped
2022-09-15T14:20:36.616Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: BlobStorageContextMiddleware: RequestMethod=GET RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:20:36 GMT","x-ms-version":"2020-04-08","content-length":"0","authorization":"SharedKey devstoreaccount1:IcqHiYxpxUJCLudd+pIsi3N4ck+dh5z+FUvIKZfVT1o="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:20:36.616Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:20:36.616Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:20:36.617Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: DispatchMiddleware: Operation=BlockBlob_GetBlockList
2022-09-15T14:20:36.617Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:20:36.617Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:20:36.617Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:20:36.617Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:20:36.618Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:20:36.618Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:20:36.618Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"GET\n\n\n\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:20:36 GMT\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\nblocklisttype:all\ncomp:blocklist"
2022-09-15T14:20:36.618Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:IcqHiYxpxUJCLudd+pIsi3N4ck+dh5z+FUvIKZfVT1o=
2022-09-15T14:20:36.618Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:20:36.618Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:20:36.618Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: HandlerMiddleware: DeserializedParameters={"options":{"listType":"all","leaseAccessConditions":{}},"comp":"blocklist","version":"2020-04-08"}
2022-09-15T14:20:36.618Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:20:36.619Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 debug: Serializer: Raw response body string is <?xml version="1.0" encoding="UTF-8" standalone="yes"?><BlockList><CommittedBlocks/><UncommittedBlocks/></BlockList>
2022-09-15T14:20:36.619Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: Serializer: Start returning stream body.
2022-09-15T14:20:36.619Z 9c01e861-d89f-43a1-9e7b-b38b7bb739f0 info: EndMiddleware: End response. TotalTimeInMS=3 StatusCode=200 StatusMessage=OK Headers={"server":"Azurite-Blob/3.19.0","last-modified":"Thu, 15 Sep 2022 14:20:36 GMT","etag":"\"0x1BC1CE69F718BB0\"","content-type":"application/xml","x-ms-blob-content-length":"0","x-ms-request-id":"9c01e861-d89f-43a1-9e7b-b38b7bb739f0","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:20:36 GMT"}

Please let me know if you would like me to provide the log for same test that skips setting the content length and doesn't see a truncate.

blueww commented 2 years ago

@nitinkgupta

The issue looks caused by you send a update metadata request which is not aligned with rest API.

From the debug log, you can see the request you use to update metadata has "Operation=BlockBlob_Upload", but in my debug log, the request has "Operation=Blob_SetMetadata".

The difference of operation is because, in Set Blob MetaData request , there are no header "content-type", "x-ms-blob-type". But the request you send has the 2 headers, so it doesn't match the Set blob metadata request format. Azurite will try the best to match it to a request, and finally matches it to the Upload Blob request. Then the upload blob request has "content-length":"0", so the blob is truncated to 0 size.

Would you please remove the 2 headers in the request to update metadata to fix this issue?

nitinkgupta commented 2 years ago

I agree that the two headers should not be included as per the documentation. Without those headers, the update metadata request works with Azurite, but fails with Azure Blob Storage. So this bug is about difference in behavior between Azurite and Blob.

Here's the log with the headers removed. Azurite works correctly with this but the same request made to Azure Blob Storage fails:

2022-09-15T14:02:20.109Z         info: Azurite Blob service is starting on 0.0.0.0:10000
2022-09-15T14:02:20.110Z         info: AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2022-09-15T14:02:20.110Z         info: AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2022-09-15T14:02:20.130Z         info: BlobGCManager:start() Starting BlobGCManager. Set status to Initializing.
2022-09-15T14:02:20.130Z         info: BlobGCManager:start() Trigger mark and sweep loop. Set status to Running.
2022-09-15T14:02:20.130Z         info: BlobGCManager:markSweepLoop() Start next mark and sweep.
2022-09-15T14:02:20.131Z         info: BlobGCManager:markSweep() Get all extents.
2022-09-15T14:02:20.131Z         info: BlobGCManager:start() BlobGCManager successfully started.
2022-09-15T14:02:20.133Z         info: BlobGCManager:markSweep() Got 0 extents.
2022-09-15T14:02:20.133Z         info: BlobGCManager:markSweep() Get referred extents.
2022-09-15T14:02:20.133Z         info: BlobGCManager:markSweep() Got referred extents, unreferenced extents count is 0.
2022-09-15T14:02:20.133Z         info: BlobGCManager:markSweepLoop() Mark and sweep finished, taken 3ms.
2022-09-15T14:02:20.133Z         info: BlobGCManager:markSweepLoop() Sleep for 600000ms.
2022-09-15T14:02:20.134Z         info: Azurite Blob service successfully listens on http://0.0.0.0:10000
2022-09-15T14:02:20.924Z 1c8193a5-7fcb-492b-b231-47c568429ced info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing?restype=container RequestHeaders:{"host":"127.0.0.1:10000","user-agent":"AZURECLI/2.38.0 (HOMEBREW) azsdk-python-storage-blob/12.12.0 Python/3.10.5 (macOS-12.5.1-x86_64-i386-64bit)","accept-encoding":"gzip, deflate","accept":"application/xml","connection":"keep-alive","x-ms-version":"2021-06-08","x-ms-client-request-id":"04232a90-34ff-11ed-96b0-acde48001122","commandname":"storage container create","parametersetname":"-n --account-name","x-ms-date":"Thu, 15 Sep 2022 14:02:20 GMT","authorization":"SharedKey devstoreaccount1:3miShD5v9r8+VTyxSNT2DgqqltXwkCHn+2RreTtp25s=","content-length":"0"} ClientIP=172.17.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:02:20.925Z 1c8193a5-7fcb-492b-b231-47c568429ced info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=
2022-09-15T14:02:20.925Z 1c8193a5-7fcb-492b-b231-47c568429ced verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:02:20.927Z 1c8193a5-7fcb-492b-b231-47c568429ced info: DispatchMiddleware: Operation=Container_Create
2022-09-15T14:02:20.928Z 1c8193a5-7fcb-492b-b231-47c568429ced verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:02:20.929Z 1c8193a5-7fcb-492b-b231-47c568429ced info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:02:20.929Z 1c8193a5-7fcb-492b-b231-47c568429ced debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:02:20.929Z 1c8193a5-7fcb-492b-b231-47c568429ced debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob:
2022-09-15T14:02:20.932Z 1c8193a5-7fcb-492b-b231-47c568429ced debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:02:20.933Z 1c8193a5-7fcb-492b-b231-47c568429ced info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:02:20.944Z 1c8193a5-7fcb-492b-b231-47c568429ced info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:04232a90-34ff-11ed-96b0-acde48001122\nx-ms-date:Thu, 15 Sep 2022 14:02:20 GMT\nx-ms-version:2021-06-08\n/devstoreaccount1/devstoreaccount1/testing\nrestype:container"
2022-09-15T14:02:20.944Z 1c8193a5-7fcb-492b-b231-47c568429ced info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:3miShD5v9r8+VTyxSNT2DgqqltXwkCHn+2RreTtp25s=
2022-09-15T14:02:20.944Z 1c8193a5-7fcb-492b-b231-47c568429ced info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:02:20.944Z 1c8193a5-7fcb-492b-b231-47c568429ced verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:02:20.946Z 1c8193a5-7fcb-492b-b231-47c568429ced info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{},"requestId":"04232a90-34ff-11ed-96b0-acde48001122"},"restype":"container","version":"2021-06-08"}
2022-09-15T14:02:20.947Z 1c8193a5-7fcb-492b-b231-47c568429ced verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:02:20.948Z 1c8193a5-7fcb-492b-b231-47c568429ced info: EndMiddleware: End response. TotalTimeInMS=24 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","etag":"\"0x21B28E349C76800\"","last-modified":"Thu, 15 Sep 2022 14:02:20 GMT","x-ms-client-request-id":"04232a90-34ff-11ed-96b0-acde48001122","x-ms-request-id":"1c8193a5-7fcb-492b-b231-47c568429ced","x-ms-version":"2021-10-04"}
2022-09-15T14:02:44.636Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=block&blockid=MSEC00000000 RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-version":"2020-04-08","content-length":"4194304","authorization":"SharedKey devstoreaccount1:U5JfZd1ZiS8jxZkz0mLkVjoNAkxMG+gvo/aIwe0Ogpo="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:02:44.636Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:02:44.636Z f953ffee-7655-4e0d-8e0a-6a856470a554 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:02:44.638Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: DispatchMiddleware: Operation=BlockBlob_StageBlock
2022-09-15T14:02:44.638Z f953ffee-7655-4e0d-8e0a-6a856470a554 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:02:44.638Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:02:44.638Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:02:44.639Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:02:44.641Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:02:44.641Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:02:44.641Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n4194304\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:02:44 GMT\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\nblockid:MSEC00000000\ncomp:block"
2022-09-15T14:02:44.641Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:U5JfZd1ZiS8jxZkz0mLkVjoNAkxMG+gvo/aIwe0Ogpo=
2022-09-15T14:02:44.641Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:02:44.641Z f953ffee-7655-4e0d-8e0a-6a856470a554 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:02:44.642Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: HandlerMiddleware: DeserializedParameters={"blockId":"MSEC00000000","options":{"leaseAccessConditions":{},"cpkInfo":{}},"comp":"block","contentLength":4194304,"version":"2020-04-08","body":"ReadableStream"}
2022-09-15T14:02:44.643Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue.operate() Schedule incoming job bd58b4ea-8076-4a29-b1c7-2828d8d003d9
2022-09-15T14:02:44.643Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:1
2022-09-15T14:02:44.644Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:1 extentId:c7882c5e-3dbd-45c9-96df-804a9df18258 offset:0 MAX_EXTENT_SIZE:67108864
2022-09-15T14:02:44.644Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:appendExtent() Get fd:undefined for extent:c7882c5e-3dbd-45c9-96df-804a9df18258 from cache.
2022-09-15T14:02:44.646Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:appendExtent() Open file:/data/__blobstorage__/c7882c5e-3dbd-45c9-96df-804a9df18258 for extent:c7882c5e-3dbd-45c9-96df-804a9df18258, get new fd:23
2022-09-15T14:02:44.646Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:appendExtent() Created write stream for fd:23
2022-09-15T14:02:44.646Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:appendExtent() Start writing to extent c7882c5e-3dbd-45c9-96df-804a9df18258
2022-09-15T14:02:44.647Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:streamPipe() Start piping data to write stream
2022-09-15T14:02:44.706Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:streamPipe() Readable stream triggers close event, 4194304 bytes piped
2022-09-15T14:02:44.706Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:streamPipe() Invoke write stream end()
2022-09-15T14:02:44.707Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:streamPipe() Writable stream triggers finish event, after 4194304 bytes piped. Flush data to fd:23.
2022-09-15T14:02:44.707Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:streamPipe() Flush data to fd:23 successfully. Resolve streamPipe().
2022-09-15T14:02:44.707Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:appendExtent() Write finish, start updating extent metadata. extent:{"id":"c7882c5e-3dbd-45c9-96df-804a9df18258","locationId":"Default","path":"c7882c5e-3dbd-45c9-96df-804a9df18258","size":4194304,"lastModifiedInMS":1663250564707}
2022-09-15T14:02:44.707Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:appendExtent() Update extent metadata done. Resolve()
2022-09-15T14:02:44.707Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue.operate() Job bd58b4ea-8076-4a29-b1c7-2828d8d003d9 completes callback, resolve.
2022-09-15T14:02:44.708Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue.operate() Schedule incoming job 85d10fee-d547-4f45-a282-cea64ca2d708
2022-09-15T14:02:44.708Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:100 operations.length:1
2022-09-15T14:02:44.708Z f953ffee-7655-4e0d-8e0a-6a856470a554 verbose: FSExtentStore:readExtent() Creating read stream. LocationId:Default extentId:c7882c5e-3dbd-45c9-96df-804a9df18258 path:/data/__blobstorage__/c7882c5e-3dbd-45c9-96df-804a9df18258 offset:0 count:4194304 end:4194303
2022-09-15T14:02:44.708Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue.operate() Job 85d10fee-d547-4f45-a282-cea64ca2d708 completes callback, resolve.
2022-09-15T14:02:44.709Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:0
2022-09-15T14:02:44.709Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:02:44.709Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:100 operations.length:0
2022-09-15T14:02:44.709Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:02:44.746Z f953ffee-7655-4e0d-8e0a-6a856470a554 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:02:44.747Z f953ffee-7655-4e0d-8e0a-6a856470a554 info: EndMiddleware: End response. TotalTimeInMS=111 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","x-ms-request-id":"f953ffee-7655-4e0d-8e0a-6a856470a554","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-request-server-encrypted":"true"}
2022-09-15T14:02:44.748Z f953ffee-7655-4e0d-8e0a-6a856470a554 debug: FSExtentStore:streamPipe() Readable stream triggers close event, 4194304 bytes piped
2022-09-15T14:02:44.748Z f953ffee-7655-4e0d-8e0a-6a856470a554 verbose: FSExtentStore:readExtent() Read stream closed. LocationId:Default extentId:c7882c5e-3dbd-45c9-96df-804a9df18258 path:/data/__blobstorage__/c7882c5e-3dbd-45c9-96df-804a9df18258 offset:0 count:4194304 end:4194303
2022-09-15T14:02:44.754Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=block&blockid=MSEC00000001 RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-version":"2020-04-08","content-length":"4194304","authorization":"SharedKey devstoreaccount1:96AQypU7ORZcYyn0n5O2Qpiut8M0JBocxyoM+HqrDBY="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:02:44.754Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:02:44.754Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:02:44.756Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: DispatchMiddleware: Operation=BlockBlob_StageBlock
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n4194304\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:02:44 GMT\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\nblockid:MSEC00000001\ncomp:block"
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:96AQypU7ORZcYyn0n5O2Qpiut8M0JBocxyoM+HqrDBY=
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:02:44.757Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:02:44.758Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: HandlerMiddleware: DeserializedParameters={"blockId":"MSEC00000001","options":{"leaseAccessConditions":{},"cpkInfo":{}},"comp":"block","contentLength":4194304,"version":"2020-04-08","body":"ReadableStream"}
2022-09-15T14:02:44.758Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue.operate() Schedule incoming job 616ff680-f317-4826-b9ae-21545e92ddd1
2022-09-15T14:02:44.758Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:1
2022-09-15T14:02:44.758Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:1 extentId:c7882c5e-3dbd-45c9-96df-804a9df18258 offset:4194304 MAX_EXTENT_SIZE:67108864
2022-09-15T14:02:44.758Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:appendExtent() Get fd:23 for extent:c7882c5e-3dbd-45c9-96df-804a9df18258 from cache.
2022-09-15T14:02:44.758Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:appendExtent() Created write stream for fd:23
2022-09-15T14:02:44.758Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:appendExtent() Start writing to extent c7882c5e-3dbd-45c9-96df-804a9df18258
2022-09-15T14:02:44.758Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:streamPipe() Start piping data to write stream
2022-09-15T14:02:44.805Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:streamPipe() Readable stream triggers close event, 4194304 bytes piped
2022-09-15T14:02:44.805Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:streamPipe() Invoke write stream end()
2022-09-15T14:02:44.805Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:streamPipe() Writable stream triggers finish event, after 4194304 bytes piped. Flush data to fd:23.
2022-09-15T14:02:44.805Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:streamPipe() Flush data to fd:23 successfully. Resolve streamPipe().
2022-09-15T14:02:44.806Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:appendExtent() Write finish, start updating extent metadata. extent:{"id":"c7882c5e-3dbd-45c9-96df-804a9df18258","locationId":"Default","path":"c7882c5e-3dbd-45c9-96df-804a9df18258","size":8388608,"lastModifiedInMS":1663250564806}
2022-09-15T14:02:44.806Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:appendExtent() Update extent metadata done. Resolve()
2022-09-15T14:02:44.806Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue.operate() Job 616ff680-f317-4826-b9ae-21545e92ddd1 completes callback, resolve.
2022-09-15T14:02:44.806Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue.operate() Schedule incoming job 916850ee-ff9a-4437-aedf-17c963814d07
2022-09-15T14:02:44.806Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:100 operations.length:1
2022-09-15T14:02:44.806Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 verbose: FSExtentStore:readExtent() Creating read stream. LocationId:Default extentId:c7882c5e-3dbd-45c9-96df-804a9df18258 path:/data/__blobstorage__/c7882c5e-3dbd-45c9-96df-804a9df18258 offset:4194304 count:4194304 end:8388607
2022-09-15T14:02:44.807Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue.operate() Job 916850ee-ff9a-4437-aedf-17c963814d07 completes callback, resolve.
2022-09-15T14:02:44.807Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:0
2022-09-15T14:02:44.807Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:02:44.807Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:100 operations.length:0
2022-09-15T14:02:44.807Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: OperationQueue:execute() return. Operation.length === 0
2022-09-15T14:02:44.831Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:02:44.831Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 info: EndMiddleware: End response. TotalTimeInMS=77 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","x-ms-request-id":"3e002887-469e-4a0f-ae31-f6c4ce4837a3","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-request-server-encrypted":"true"}
2022-09-15T14:02:44.832Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 debug: FSExtentStore:streamPipe() Readable stream triggers close event, 4194304 bytes piped
2022-09-15T14:02:44.832Z 3e002887-469e-4a0f-ae31-f6c4ce4837a3 verbose: FSExtentStore:readExtent() Read stream closed. LocationId:Default extentId:c7882c5e-3dbd-45c9-96df-804a9df18258 path:/data/__blobstorage__/c7882c5e-3dbd-45c9-96df-804a9df18258 offset:4194304 count:4194304 end:8388607
2022-09-15T14:02:44.846Z 31103872-83a6-45f8-8652-1b952646aebd info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-version":"2020-04-08","x-ms-meta-edgeattr":"AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==","content-length":"121","authorization":"SharedKey devstoreaccount1:iuyeruWaHx1dMVor0i2gr1R2sCqSdvaCb6lN4geE/ak="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:02:44.846Z 31103872-83a6-45f8-8652-1b952646aebd info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:02:44.846Z 31103872-83a6-45f8-8652-1b952646aebd verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:02:44.847Z 31103872-83a6-45f8-8652-1b952646aebd info: DispatchMiddleware: Operation=BlockBlob_CommitBlockList
2022-09-15T14:02:44.847Z 31103872-83a6-45f8-8652-1b952646aebd verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:02:44.847Z 31103872-83a6-45f8-8652-1b952646aebd info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:02:44.847Z 31103872-83a6-45f8-8652-1b952646aebd debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:02:44.847Z 31103872-83a6-45f8-8652-1b952646aebd debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:02:44.847Z 31103872-83a6-45f8-8652-1b952646aebd debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:02:44.847Z 31103872-83a6-45f8-8652-1b952646aebd info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:02:44.847Z 31103872-83a6-45f8-8652-1b952646aebd info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n121\n\ntext/plain\n\n\n\n\n\n\nx-ms-date:Thu, 15 Sep 2022 14:02:44 GMT\nx-ms-meta-edgeattr:AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\ncomp:blocklist"
2022-09-15T14:02:44.848Z 31103872-83a6-45f8-8652-1b952646aebd info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:iuyeruWaHx1dMVor0i2gr1R2sCqSdvaCb6lN4geE/ak=
2022-09-15T14:02:44.848Z 31103872-83a6-45f8-8652-1b952646aebd info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:02:44.848Z 31103872-83a6-45f8-8652-1b952646aebd verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:02:44.848Z 31103872-83a6-45f8-8652-1b952646aebd debug: deserialize(): Raw request body string is (removed all empty characters) <?xmlversion="1.0"encoding="utf-8"?><BlockList><Latest>MSEC00000000</Latest><Latest>MSEC00000001</Latest></BlockList>
2022-09-15T14:02:44.851Z 31103872-83a6-45f8-8652-1b952646aebd info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{"edgeattr":"AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA=="},"blobHTTPHeaders":{},"leaseAccessConditions":{},"cpkInfo":{},"modifiedAccessConditions":{}},"comp":"blocklist","version":"2020-04-08","blocks":{"committed":[],"uncommitted":[],"latest":["MSEC00000000","MSEC00000001"]},"body":"ReadableStream"}
2022-09-15T14:02:44.854Z 31103872-83a6-45f8-8652-1b952646aebd verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:02:44.854Z 31103872-83a6-45f8-8652-1b952646aebd info: EndMiddleware: End response. TotalTimeInMS=9 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","etag":"\"0x1E6D2C010A0A820\"","last-modified":"Thu, 15 Sep 2022 14:02:44 GMT","content-md5":"qS8XBEcWJncimGMJYf6pPg==","x-ms-request-id":"31103872-83a6-45f8-8652-1b952646aebd","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-request-server-encrypted":"true"}
2022-09-15T14:02:44.867Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: BlobStorageContextMiddleware: RequestMethod=GET RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-version":"2020-04-08","content-length":"0","authorization":"SharedKey devstoreaccount1:typ4SZd1YVzt+OXseWyQHSjDPjsYk0jjtbPDChbaCDU="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:02:44.867Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:02:44.867Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:02:44.868Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: DispatchMiddleware: Operation=BlockBlob_GetBlockList
2022-09-15T14:02:44.868Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:02:44.868Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:02:44.868Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:02:44.868Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:02:44.869Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:02:44.869Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:02:44.869Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"GET\n\n\n\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:02:44 GMT\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\nblocklisttype:all\ncomp:blocklist"
2022-09-15T14:02:44.869Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:typ4SZd1YVzt+OXseWyQHSjDPjsYk0jjtbPDChbaCDU=
2022-09-15T14:02:44.869Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:02:44.869Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:02:44.869Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: HandlerMiddleware: DeserializedParameters={"options":{"listType":"all","leaseAccessConditions":{}},"comp":"blocklist","version":"2020-04-08"}
2022-09-15T14:02:44.869Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:02:44.870Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 debug: Serializer: Raw response body string is <?xml version="1.0" encoding="UTF-8" standalone="yes"?><BlockList><CommittedBlocks><Block><Name>MSEC00000000</Name><Size>4194304</Size></Block><Block><Name>MSEC00000001</Name><Size>4194304</Size></Block></CommittedBlocks><UncommittedBlocks/></BlockList>
2022-09-15T14:02:44.870Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: Serializer: Start returning stream body.
2022-09-15T14:02:44.870Z db13ad11-84c2-46c6-9c5d-0cdaa79dff93 info: EndMiddleware: End response. TotalTimeInMS=3 StatusCode=200 StatusMessage=OK Headers={"server":"Azurite-Blob/3.19.0","last-modified":"Thu, 15 Sep 2022 14:02:44 GMT","etag":"\"0x1E6D2C010A0A820\"","content-type":"application/xml","x-ms-blob-content-length":"8388608","x-ms-request-id":"db13ad11-84c2-46c6-9c5d-0cdaa79dff93","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:02:44 GMT"}
2022-09-15T14:02:44.885Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=metadata RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-version":"2020-04-08","x-ms-meta-edgeattr":"AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==","authorization":"SharedKey devstoreaccount1:2r/fRGlv4vINx8L7WlZS0GHgzyREKA3+LwC8DmE9Y2M="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:02:44.885Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:02:44.885Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:02:44.886Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: DispatchMiddleware: Operation=Blob_SetMetadata
2022-09-15T14:02:44.886Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:02:44.886Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:02:44.886Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:02:44.886Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:02:44.886Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:02:44.886Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:02:44.887Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:02:44 GMT\nx-ms-meta-edgeattr:AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\ncomp:metadata"
2022-09-15T14:02:44.887Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:2r/fRGlv4vINx8L7WlZS0GHgzyREKA3+LwC8DmE9Y2M=
2022-09-15T14:02:44.887Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:02:44.887Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:02:44.888Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{"edgeattr":"AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA=="},"leaseAccessConditions":{},"cpkInfo":{},"modifiedAccessConditions":{}},"comp":"metadata","version":"2020-04-08"}
2022-09-15T14:02:44.888Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:02:44.888Z 2c013f6b-e66a-4ee9-a793-7425a5f091b5 info: EndMiddleware: End response. TotalTimeInMS=4 StatusCode=200 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.19.0","etag":"\"0x221B984E10A2040\"","last-modified":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-request-id":"2c013f6b-e66a-4ee9-a793-7425a5f091b5","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-request-server-encrypted":"true"}
2022-09-15T14:02:44.895Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: BlobStorageContextMiddleware: RequestMethod=GET RequestURL=http://127.0.0.1/devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all RequestHeaders:{"host":"127.0.0.1","content-type":"text/plain","x-ms-blob-type":"BlockBlob","x-ms-date":"Thu, 15 Sep 2022 14:02:44 GMT","x-ms-version":"2020-04-08","content-length":"0","authorization":"SharedKey devstoreaccount1:typ4SZd1YVzt+OXseWyQHSjDPjsYk0jjtbPDChbaCDU="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-15T14:02:44.895Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=testing Blob=blobclient.updateattrs
2022-09-15T14:02:44.895Z 29a07c30-c413-43ea-afe4-a2eb01f944bf verbose: DispatchMiddleware: Dispatching request...
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: DispatchMiddleware: Operation=BlockBlob_GetBlockList
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: PublicAccessAuthenticator:validate() Start validation against public access.
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf debug: PublicAccessAuthenticator:validate() Getting account properties...
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: testing, blob: blobclient.updateattrs
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container testing
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"GET\n\n\n\n\ntext/plain\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-date:Thu, 15 Sep 2022 14:02:44 GMT\nx-ms-version:2020-04-08\n/devstoreaccount1/devstoreaccount1/testing/blobclient.updateattrs\nblocklisttype:all\ncomp:blocklist"
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:typ4SZd1YVzt+OXseWyQHSjDPjsYk0jjtbPDChbaCDU=
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-15T14:02:44.896Z 29a07c30-c413-43ea-afe4-a2eb01f944bf verbose: DeserializerMiddleware: Start deserializing...
2022-09-15T14:02:44.897Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: HandlerMiddleware: DeserializedParameters={"options":{"listType":"all","leaseAccessConditions":{}},"comp":"blocklist","version":"2020-04-08"}
2022-09-15T14:02:44.897Z 29a07c30-c413-43ea-afe4-a2eb01f944bf verbose: SerializerMiddleware: Start serializing...
2022-09-15T14:02:44.897Z 29a07c30-c413-43ea-afe4-a2eb01f944bf debug: Serializer: Raw response body string is <?xml version="1.0" encoding="UTF-8" standalone="yes"?><BlockList><CommittedBlocks><Block><Name>MSEC00000000</Name><Size>4194304</Size></Block><Block><Name>MSEC00000001</Name><Size>4194304</Size></Block></CommittedBlocks><UncommittedBlocks/></BlockList>
2022-09-15T14:02:44.897Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: Serializer: Start returning stream body.
2022-09-15T14:02:44.897Z 29a07c30-c413-43ea-afe4-a2eb01f944bf info: EndMiddleware: End response. TotalTimeInMS=2 StatusCode=200 StatusMessage=OK Headers={"server":"Azurite-Blob/3.19.0","last-modified":"Thu, 15 Sep 2022 14:02:44 GMT","etag":"\"0x221B984E10A2040\"","content-type":"application/xml","x-ms-blob-content-length":"8388608","x-ms-request-id":"29a07c30-c413-43ea-afe4-a2eb01f944bf","x-ms-version":"2021-10-04","date":"Thu, 15 Sep 2022 14:02:44 GMT"}
blueww commented 2 years ago

@nitinkgupta The request without these 2 headers should not fail on server. If it failed, would you please send the request trace (hide credential) with request ID, so we can see why it failed on server.

Following is a set metadata request I send to server without the 2 headers, and it success:

PUT https://[accountName].blob.core.windows.net/test2/testblob?comp=metadata HTTP/1.1
x-ms-meta-key1: value1
x-ms-client-request-id: 73e5032e-85fc-40ad-a23b-0fa97512de4d
User-Agent: Azure-Storage/11.2.2 (.NET Core; Win32NT 10.0.19044.0)
x-ms-version: 2019-07-07
x-ms-date: Tue, 20 Sep 2022 03:32:04 GMT
Authorization: SharedKey [accountName]:***
Host: [accountName].blob.core.windows.net
Content-Length: 0
Connection: Keep-Alive

HTTP/1.1 200 OK
Content-Length: 0
Last-Modified: Tue, 20 Sep 2022 03:33:06 GMT
ETag: "0x8DA9AB8D4ECD8E2"
Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id: 5babb792-501e-0006-55a1-cce97d000000
x-ms-client-request-id: 73e5032e-85fc-40ad-a23b-0fa97512de4d
x-ms-version: 2019-07-07
x-ms-request-server-encrypted: true
Date: Tue, 20 Sep 2022 03:33:05 GMT
nitinkgupta commented 2 years ago

Thanks for looking into this. I'll reproduce the issue and send the log. I'm currently busy with a work priority so it may take a few days.

nitinkgupta commented 2 years ago

Sorry for the delay in responding. I would like to focus on the original problem that azurite is truncating the file on a metadata write, when Azure blob storage does not.

My test does the following steps:

Here's the REST calls and responses from Azure blob storage:

REST sendop: PUT /testing/blobclient.updateattrs?comp=block&blockid=MSEC00000000 HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:05:58 GMT
x-ms-version: 2020-04-08
Content-Length: 4194304
Authorization: SharedKey REDACTED

Content-Length:0
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:7d86d439-d01e-001d-40bd-d26b14000000
x-ms-version:2020-04-08
x-ms-content-crc64:a6mGT0pdNRI=
x-ms-request-server-encrypted:true
Date:Tue, 27 Sep 2022 22:06:03 GMT

REST sendop: PUT /testing/blobclient.updateattrs?comp=block&blockid=MSEC00000001 HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:06:03 GMT
x-ms-version: 2020-04-08
Content-Length: 4194304
Authorization: SharedKey REDACTED

Content-Length:0
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:7d86d9a0-d01e-001d-19bd-d26b14000000
x-ms-version:2020-04-08
x-ms-content-crc64:a6mGT0pdNRI=
x-ms-request-server-encrypted:true
Date:Tue, 27 Sep 2022 22:06:11 GMT

REST sendop: PUT /testing/blobclient.updateattrs?comp=blocklist HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-date: Tue, 27 Sep 2022 22:06:12 GMT
x-ms-version: 2020-04-08
x-ms-meta-someattr: AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==
Content-Length: 121
Authorization: SharedKey REDACTED

Content-Length:0
Last-Modified:Tue, 27 Sep 2022 22:06:12 GMT
ETag:"0x8DAA0D47DA3C2F5"
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:7d86e38e-d01e-001d-5cbd-d26b14000000
x-ms-version:2020-04-08
x-ms-content-crc64:9GIuV+RVLCA=
x-ms-request-server-encrypted:true
Date:Tue, 27 Sep 2022 22:06:12 GMT

REST sendop: GET /testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:06:12 GMT
x-ms-version: 2020-04-08
Content-Length: 0
Authorization: SharedKey REDACTED

Transfer-Encoding:chunked
Content-Type:application/xml
Last-Modified:Tue, 27 Sep 2022 22:06:12 GMT
ETag:"0x8DAA0D47DA3C2F5"
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:7d86e39a-d01e-001d-61bd-d26b14000000
x-ms-version:2020-04-08
x-ms-blob-content-length:8388608
Date:Tue, 27 Sep 2022 22:06:12 GMT

REST sendop: PUT /testing/blobclient.updateattrs?comp=metadata HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:06:12 GMT
x-ms-version: 2020-04-08
x-ms-meta-someattr: AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==
Content-Length: 0
Authorization: SharedKey REDACTED

Content-Length:0
Last-Modified:Tue, 27 Sep 2022 22:06:12 GMT
ETag:"0x8DAA0D47DB1CAB9"
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:7d86e39e-d01e-001d-65bd-d26b14000000
x-ms-version:2020-04-08
x-ms-request-server-encrypted:true
Date:Tue, 27 Sep 2022 22:06:12 GMT

REST sendop: GET /testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:06:13 GMT
x-ms-version: 2020-04-08
Content-Length: 0
Authorization: SharedKey REDACTED

Transfer-Encoding:chunked
Content-Type:application/xml
Last-Modified:Tue, 27 Sep 2022 22:06:12 GMT
ETag:"0x8DAA0D47DB1CAB9"
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:7d86e3c1-d01e-001d-03bd-d26b14000000
x-ms-version:2020-04-08
x-ms-blob-content-length:8388608
Date:Tue, 27 Sep 2022 22:06:12 GMT

The GET block list above returned the correct file size in x-ms-blob-content-length header above. Here is the REST log from Azurite doing the exact same sequence of calls:

REST sendop: PUT /devstoreaccount1/testing/blobclient.updateattrs?comp=block&blockid=MSEC00000000 HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:16:41 GMT
x-ms-version: 2020-04-08
Content-Length: 4194304
Authorization: SharedKey REDACTED

Server:Azurite-Blob/3.19.0
x-ms-request-id:be9900c1-7dbb-43cb-b592-8d4ff08a5d1d
x-ms-version:2021-10-04
date:Tue, 27 Sep 2022 22:16:41 GMT
x-ms-request-server-encrypted:true
Connection:keep-alive
Keep-Alive:timeout=5
Content-Length:0

REST sendop: PUT /devstoreaccount1/testing/blobclient.updateattrs?comp=block&blockid=MSEC00000001 HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:16:41 GMT
x-ms-version: 2020-04-08
Content-Length: 4194304
Authorization: SharedKey REDACTED

Server:Azurite-Blob/3.19.0
x-ms-request-id:faa82db9-d52c-41a8-acb6-898943d8a7a3
x-ms-version:2021-10-04
date:Tue, 27 Sep 2022 22:16:41 GMT
x-ms-request-server-encrypted:true
Connection:keep-alive
Keep-Alive:timeout=5
Content-Length:0

REST sendop: PUT /devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-date: Tue, 27 Sep 2022 22:16:41 GMT
x-ms-version: 2020-04-08
x-ms-meta-someattr: AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==
Content-Length: 121
Authorization: SharedKey REDACTED

Server:Azurite-Blob/3.19.0
etag:"0x1F404FBA61EEA10"
last-modified:Tue, 27 Sep 2022 22:16:41 GMT
content-md5:qS8XBEcWJncimGMJYf6pPg==
x-ms-request-id:97d7713d-f305-40c2-93e5-fc9cd0e2b669
x-ms-version:2021-10-04
date:Tue, 27 Sep 2022 22:16:41 GMT
x-ms-request-server-encrypted:true
Connection:keep-alive
Keep-Alive:timeout=5
Content-Length:0

REST sendop: GET /devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:16:41 GMT
x-ms-version: 2020-04-08
Content-Length: 0
Authorization: SharedKey REDACTED

Server:Azurite-Blob/3.19.0
last-modified:Tue, 27 Sep 2022 22:16:41 GMT
etag:"0x1F404FBA61EEA10"
content-type:application/xml
x-ms-blob-content-length:8388608
x-ms-request-id:0ac4f1b0-67f3-4ed6-a565-eb1ade8209e2
x-ms-version:2021-10-04
date:Tue, 27 Sep 2022 22:16:41 GMT
Connection:keep-alive
Keep-Alive:timeout=5
Transfer-Encoding:chunked

REST sendop: PUT /devstoreaccount1/testing/blobclient.updateattrs?comp=metadata HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:16:41 GMT
x-ms-version: 2020-04-08
x-ms-meta-someattr: AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==
Content-Length: 0
Authorization: SharedKey REDACTED

Server:Azurite-Blob/3.19.0
etag:"0x23A67EB3FEF2700"
last-modified:Tue, 27 Sep 2022 22:16:41 GMT
content-md5:1B2M2Y8AsgTpgAmY7PhCfg==
x-ms-request-id:bb46ecac-8366-49be-b331-e554d5596c35
x-ms-version:2021-10-04
date:Tue, 27 Sep 2022 22:16:41 GMT
x-ms-request-server-encrypted:true
Connection:keep-alive
Keep-Alive:timeout=5
Content-Length:0

REST sendop: GET /devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Tue, 27 Sep 2022 22:16:41 GMT
x-ms-version: 2020-04-08
Content-Length: 0
Authorization: SharedKey REDACTED

Server:Azurite-Blob/3.19.0
last-modified:Tue, 27 Sep 2022 22:16:41 GMT
etag:"0x23A67EB3FEF2700"
content-type:application/xml
x-ms-blob-content-length:0
x-ms-request-id:c5a50c9d-412a-4151-b0ac-af2e71f76f34
x-ms-version:2021-10-04
date:Tue, 27 Sep 2022 22:16:41 GMT
Connection:keep-alive
Keep-Alive:timeout=5
Transfer-Encoding:chunked

As seen above, x-ms-blob-content-length:0 is returned from Azurite, because it considered the PUT Metadata as a PUT Blob operation.

blueww commented 2 years ago

@nitinkgupta

As the commented above, the problem is caused by the request you send to update the blob metadata, is not aligned with the rest API of Set Blob MetaData.

The difference is for set blob metadata request, there should be no header "content-type", "x-ms-blob-type". But the request you send has the 2 headers, so it doesn't match the Set blob metadata request format.

Please remove the 2 headers from the request of update the blob metadata, then try again. Feel free to let us know if you still see any issue after remove the 2 headers.

nitinkgupta commented 2 years ago

Thank you for the prompt response. Like I mentioned before, if I don't provide the content-type and x-ms-blob-type headers, blob storage returns a 411 error asking for content-length, even though the Set Blob MetaData rest API doc doesn't mention it:

REST sendop: PUT /testing/blobclient.updateattrs?comp=block&blockid=MSEC00000000 HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Thu, 29 Sep 2022 21:21:24 GMT
x-ms-version: 2020-04-08
Content-Length: 4194304
Authorization: SharedKey

Content-Length:0
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:4205f4f8-d01e-006f-3d49-d46c5b000000
x-ms-version:2020-04-08
x-ms-content-crc64:a6mGT0pdNRI=
x-ms-request-server-encrypted:true
Date:Thu, 29 Sep 2022 21:21:26 GMT

REST sendop: PUT /testing/blobclient.updateattrs?comp=block&blockid=MSEC00000001 HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Thu, 29 Sep 2022 21:21:26 GMT
x-ms-version: 2020-04-08
Content-Length: 4194304
Authorization: SharedKey

Content-Length:0
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:4205f7ac-d01e-006f-3f49-d46c5b000000
x-ms-version:2020-04-08
x-ms-content-crc64:a6mGT0pdNRI=
x-ms-request-server-encrypted:true
Date:Thu, 29 Sep 2022 21:21:27 GMT

REST sendop: PUT /testing/blobclient.updateattrs?comp=blocklist HTTP/1.1
Host: nitigupsa.blob.core.windows.net
x-ms-date: Thu, 29 Sep 2022 21:21:27 GMT
x-ms-version: 2020-04-08
x-ms-meta-someattr: AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==
Content-Length: 121
Authorization: SharedKey

Content-Length:0
Last-Modified:Thu, 29 Sep 2022 21:21:27 GMT
ETag:"0x8DAA260922EC2A8"
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:4205fa76-d01e-006f-3349-d46c5b000000
x-ms-version:2020-04-08
x-ms-content-crc64:9GIuV+RVLCA=
x-ms-request-server-encrypted:true
Date:Thu, 29 Sep 2022 21:21:27 GMT

REST sendop: GET /testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all HTTP/1.1
Host: nitigupsa.blob.core.windows.net
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Thu, 29 Sep 2022 21:21:27 GMT
x-ms-version: 2020-04-08
Content-Length: 0
Authorization: SharedKey

Transfer-Encoding:chunked
Content-Type:application/xml
Last-Modified:Thu, 29 Sep 2022 21:21:27 GMT
ETag:"0x8DAA260922EC2A8"
Server:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
x-ms-request-id:4205fa95-d01e-006f-5149-d46c5b000000
x-ms-version:2020-04-08
x-ms-blob-content-length:8388608
Date:Thu, 29 Sep 2022 21:21:27 GMT

REST sendop: PUT /testing/blobclient.updateattrs?comp=metadata HTTP/1.1
Host: nitigupsa.blob.core.windows.net
x-ms-date: Thu, 29 Sep 2022 21:21:27 GMT
x-ms-version: 2020-04-08
x-ms-meta-someattr: AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==
Authorization: SharedKey

Content-Type:text/html; charset=us-ascii
Server:Microsoft-HTTPAPI/2.0
Date:Thu, 29 Sep 2022 21:21:28 GMT
Connection:close
Content-Length:344
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML
4.01//EN"http://www.w3.org/TR/html4/strict.dtd">
<HTML><HEAD><TITLE>Length Required</TITLE>
<META HTTP-EQUIV="Content-Type" Content="text/html; charset=us-ascii"></HEAD>
<BODY><h2>Length Required</h2>
<hr><p>HTTP Error 411. The request must be chunked or have a content
length.</p>
</BODY></HTML>

But azurite is OK with the exact same request:

REST sendop: PUT /devstoreaccount1/testing/blobclient.updateattrs?comp=block&blockid=MSEC00000000 HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Thu, 29 Sep 2022 21:29:10 GMT
x-ms-version: 2020-04-08
Content-Length: 4194304
Authorization: SharedKey

Server:Azurite-Blob/3.19.0
x-ms-request-id:695ae9cd-e04a-4e01-8b88-bd2b7f66e888
x-ms-version:2021-10-04
date:Thu, 29 Sep 2022 21:29:10 GMT
x-ms-request-server-encrypted:true
Connection:keep-alive
Keep-Alive:timeout=5
Content-Length:0

REST sendop: PUT /devstoreaccount1/testing/blobclient.updateattrs?comp=block&blockid=MSEC00000001 HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Thu, 29 Sep 2022 21:29:10 GMT
x-ms-version: 2020-04-08
Content-Length: 4194304
Authorization: SharedKey

Server:Azurite-Blob/3.19.0
x-ms-request-id:555618b2-4531-4f61-8f77-a2b768a7a1bd
x-ms-version:2021-10-04
date:Thu, 29 Sep 2022 21:29:10 GMT
x-ms-request-server-encrypted:true
Connection:keep-alive
Keep-Alive:timeout=5
Content-Length:0

REST sendop: PUT /devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist HTTP/1.1
Host: 127.0.0.1
x-ms-date: Thu, 29 Sep 2022 21:29:10 GMT
x-ms-version: 2020-04-08
x-ms-meta-someattr: AQB4eKQBAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==
Content-Length: 121
Authorization: SharedKey

Server:Azurite-Blob/3.19.0
etag:"0x22BFB6E4526A4C0"
last-modified:Thu, 29 Sep 2022 21:29:10 GMT
content-md5:qS8XBEcWJncimGMJYf6pPg==
x-ms-request-id:78f79afd-6a87-4d2a-a659-64f46ff6ec1a
x-ms-version:2021-10-04
date:Thu, 29 Sep 2022 21:29:10 GMT
x-ms-request-server-encrypted:true
Connection:keep-alive
Keep-Alive:timeout=5
Content-Length:0

REST sendop: GET /devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Thu, 29 Sep 2022 21:29:10 GMT
x-ms-version: 2020-04-08
Content-Length: 0
Authorization: SharedKey

Server:Azurite-Blob/3.19.0
last-modified:Thu, 29 Sep 2022 21:29:10 GMT
etag:"0x22BFB6E4526A4C0"
content-type:application/xml
x-ms-blob-content-length:8388608
x-ms-request-id:4826d62e-e48d-4237-a097-d89a03508d64
x-ms-version:2021-10-04
date:Thu, 29 Sep 2022 21:29:10 GMT
Connection:keep-alive
Keep-Alive:timeout=5
Transfer-Encoding:chunked

REST sendop: PUT /devstoreaccount1/testing/blobclient.updateattrs?comp=metadata HTTP/1.1
Host: 127.0.0.1
x-ms-date: Thu, 29 Sep 2022 21:29:10 GMT
x-ms-version: 2020-04-08
x-ms-meta-someattr: AQB4eIABAAAAAAAAAAAAALsFR2IAAAAAAAAAAAAAAAC7BUdiAAAAAAAAAAAAAAAAuwVHYgAAAAAAAAAAAAAAAA==
Authorization: SharedKey

Server:Azurite-Blob/3.19.0
etag:"0x1C8EE93815AF680"
last-modified:Thu, 29 Sep 2022 21:29:10 GMT
x-ms-request-id:f54dcbd7-39a3-49b6-93dc-29d3bc656147
x-ms-version:2021-10-04
date:Thu, 29 Sep 2022 21:29:10 GMT
x-ms-request-server-encrypted:true
Connection:keep-alive
Keep-Alive:timeout=5
Content-Length:0

REST sendop: GET /devstoreaccount1/testing/blobclient.updateattrs?comp=blocklist&blocklisttype=all HTTP/1.1
Host: 127.0.0.1
Content-Type: text/plain
x-ms-blob-type: BlockBlob
x-ms-date: Thu, 29 Sep 2022 21:29:10 GMT
x-ms-version: 2020-04-08
Content-Length: 0
Authorization: SharedKey

Server:Azurite-Blob/3.19.0
last-modified:Thu, 29 Sep 2022 21:29:10 GMT
etag:"0x1C8EE93815AF680"
content-type:application/xml
x-ms-blob-content-length:8388608
x-ms-request-id:ff1e8362-153c-4f8d-8a99-0e57879ca8d3
x-ms-version:2021-10-04
date:Thu, 29 Sep 2022 21:29:10 GMT
Connection:keep-alive
Keep-Alive:timeout=5
Transfer-Encoding:chunked

I am able to get azurite and blob storage to do the ops successfully if:

So, thank you for helping me arrive at a set of headers that both Azurite and Blob Storage agree on. This helps me have common code that works for both of them.

However, I still expect Azurite to work with the same headers that Blob Storage works with. Inconsistencies between the two should be considered a bug in Azurite or in Blob Storage.

blueww commented 2 years ago

@nitinkgupta Good to know that you have make both Azurite and Azure server works!

Thanks for the suggestion! However, Azurite code to differ the request type is generated from rest API swagger, so it only commits to handle the request aligned with rest API correctly. If the request is not aligned with any rest API design, Azurite can't commit the behavior (or there will be too many corner cases to handle).

Please do send the request aligned with rest API to make both Azurite and Azure works. Thanks for your understanding!