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

Client request ID header x-ms-client-request-id is not returned in some cases (errors?) #2265

Open joelverhagen opened 1 year ago

joelverhagen commented 1 year ago

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

Confirmed on blob and table, likely exists for the other APIs

Which version of the Azurite was used?

3.27.0

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

VS Code extension

What's the Node.js version?

v18.18.2

What problem was encountered?

Some error responses that come back from Azurite do not echo the x-ms-client-request-id request header as a response header. This works for successful requests in all the cases I have tried. This is a different behavior from real Azure Storage. Consider the "create blob container" or "create table" APIs. These return a 409 Conflict when the entities already exist. Azurite does not return the x-ms-client-request-id response header on 409 but Azure Storage does.

Steps to reproduce the issue?

Debug log:

2023-10-26T16:10:27.136Z     info: Azurite Blob service is starting on 127.0.0.1:10000
2023-10-26T16:10:27.137Z     info: AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2023-10-26T16:10:27.137Z     info: AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2023-10-26T16:10:27.162Z     info: BlobGCManager:start() Starting BlobGCManager. Set status to Initializing.
2023-10-26T16:10:27.163Z     info: BlobGCManager:start() Trigger mark and sweep loop. Set status to Running.
2023-10-26T16:10:27.163Z     info: BlobGCManager:markSweepLoop() Start next mark and sweep.
2023-10-26T16:10:27.163Z     info: BlobGCManager:markSweep() Get all extents.
2023-10-26T16:10:27.164Z     info: BlobGCManager:start() BlobGCManager successfully started.
2023-10-26T16:10:27.173Z     info: BlobGCManager:markSweep() Got 1 extents.
2023-10-26T16:10:27.173Z     info: BlobGCManager:markSweep() Get referred extents.
2023-10-26T16:10:27.173Z     info: BlobGCManager:markSweep() Got referred extents, unreferenced extents count is 0.
2023-10-26T16:10:27.174Z     info: BlobGCManager:markSweepLoop() Mark and sweep finished, taken 11ms.
2023-10-26T16:10:27.174Z     info: BlobGCManager:markSweepLoop() Sleep for 600000ms.
2023-10-26T16:10:27.176Z     info: Azurite Blob service successfully listens on http://127.0.0.1:10000
2023-10-26T16:10:27.176Z     info: Azurite Queue service is starting on 127.0.0.1:10001
2023-10-26T16:10:27.177Z     info: AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2023-10-26T16:10:27.177Z     info: AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2023-10-26T16:10:27.208Z     info: QueueGCManager:start() Starting QueueGCManager, set status to Initializing
2023-10-26T16:10:27.208Z     info: QueueGCManager:start() Trigger mark and sweep loop, set status to Running.
2023-10-26T16:10:27.209Z     info: QueueGCManager:markSweepLoop() Start next mark and sweep.
2023-10-26T16:10:27.209Z     info: QueueGCManger:markSweep() Get all extents.
2023-10-26T16:10:27.209Z     info: QueueGCManager:start() QueueGCManager successfully started.
2023-10-26T16:10:27.209Z     info: QueueGCManager:marksweep() Get 0 extents.
2023-10-26T16:10:27.209Z     info: QueueGCManager:markSweep() Get referred extents, then remove from allExtents.
2023-10-26T16:10:27.209Z     info: QueueGCManager:markSweep() Got referred extents, unreferenced extents count is 0.
2023-10-26T16:10:27.209Z     info: QueueGCManager:markSweepLoop() Mark and sweep finished, taken 0ms.
2023-10-26T16:10:27.209Z     info: QueueGCManager:markSweepLoop() Sleep for 60000ms.
2023-10-26T16:10:27.210Z     info: Azurite Queue service successfully listens on http://127.0.0.1:10001
2023-10-26T16:10:27.211Z     info: Azurite Table service is starting on 127.0.0.1:10002
2023-10-26T16:10:27.211Z     info: AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2023-10-26T16:10:27.211Z     info: AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2023-10-26T16:10:27.224Z     info: Azurite Table service successfully listens on http://127.0.0.1:10002
2023-10-26T16:10:28.636Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/test?restype=container RequestHeaders:{"host":"127.0.0.1:10000","x-ms-version":"2023-08-03","accept":"application/xml","x-ms-client-request-id":"5cc894f7-cde1-49cd-b4d1-5016fcc655cc","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Blobs/12.18.0 (.NET 7.0.12; Microsoft Windows 10.0.22621)","x-ms-date":"Thu, 26 Oct 2023 16:10:28 GMT","authorization":"SharedKey devstoreaccount1:/QAdcx3K7Z3iMqPUg2JrJvdI+g/oSYa5IKOeRTEBgx0=","content-length":"0"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2023-10-26T16:10:28.636Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=test Blob=
2023-10-26T16:10:28.636Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 verbose: DispatchMiddleware: Dispatching request...
2023-10-26T16:10:28.639Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: DispatchMiddleware: Operation=Container_Create
2023-10-26T16:10:28.639Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2023-10-26T16:10:28.640Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: PublicAccessAuthenticator:validate() Start validation against public access.
2023-10-26T16:10:28.640Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 debug: PublicAccessAuthenticator:validate() Getting account properties...
2023-10-26T16:10:28.640Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: test, blob: 
2023-10-26T16:10:28.641Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container test
2023-10-26T16:10:28.641Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2023-10-26T16:10:28.653Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:5cc894f7-cde1-49cd-b4d1-5016fcc655cc\nx-ms-date:Thu, 26 Oct 2023 16:10:28 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2023-08-03\n/devstoreaccount1/devstoreaccount1/test\nrestype:container"
2023-10-26T16:10:28.653Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:/QAdcx3K7Z3iMqPUg2JrJvdI+g/oSYa5IKOeRTEBgx0=
2023-10-26T16:10:28.653Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2023-10-26T16:10:28.654Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 verbose: DeserializerMiddleware: Start deserializing...
2023-10-26T16:10:28.655Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{},"requestId":"5cc894f7-cde1-49cd-b4d1-5016fcc655cc","containerCpkScopeInfo":{}},"restype":"container","version":"2023-08-03"}
2023-10-26T16:10:28.660Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 error: ErrorMiddleware: Received a MiddlewareError, fill error information to HTTP response
2023-10-26T16:10:28.671Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 error: ErrorMiddleware: ErrorName=StorageError ErrorMessage=The specified container already exists.  ErrorHTTPStatusCode=409 ErrorHTTPStatusMessage=The specified container already exists. ErrorHTTPHeaders={"x-ms-error-code":"ContainerAlreadyExists","x-ms-request-id":"97e865a9-62f3-4d6c-bfe8-488dd6c96a30"} ErrorHTTPBody="<?xml version=\"1.0\" encoding=\"UTF-8\" standalone=\"yes\"?>\n<Error>\n  <Code>ContainerAlreadyExists</Code>\n  <Message>The specified container already exists.\nRequestId:97e865a9-62f3-4d6c-bfe8-488dd6c96a30\nTime:2023-10-26T16:10:28.656Z</Message>\n</Error>" ErrorStack="StorageError: The specified container already exists.\n    at Function.getContainerAlreadyExists (C:\\z\\Git\\joelverhagen\\Azurite\\src\\blob\\errors\\StorageErrorFactory.ts:48:12)\n    at LokiBlobMetadataStore.createContainer (C:\\z\\Git\\joelverhagen\\Azurite\\src\\blob\\persistence\\LokiBlobMetadataStore.ts:389:33)\n    at ContainerHandler.create (C:\\z\\Git\\joelverhagen\\Azurite\\src\\blob\\handlers\\ContainerHandler.ts:70:30)\n    at C:\\z\\Git\\joelverhagen\\Azurite\\src\\blob\\generated\\middleware\\HandlerMiddlewareFactory.ts:82:10\n    at C:\\z\\Git\\joelverhagen\\Azurite\\src\\blob\\generated\\ExpressMiddlewareFactory.ts:98:57\n    at Layer.handle [as handle_request] (C:\\z\\Git\\joelverhagen\\Azurite\\node_modules\\express\\lib\\router\\layer.js:95:5)\n    at trim_prefix (C:\\z\\Git\\joelverhagen\\Azurite\\node_modules\\express\\lib\\router\\index.js:328:13)\n    at C:\\z\\Git\\joelverhagen\\Azurite\\node_modules\\express\\lib\\router\\index.js:286:9\n    at Function.process_params (C:\\z\\Git\\joelverhagen\\Azurite\\node_modules\\express\\lib\\router\\index.js:346:12)\n    at next (C:\\z\\Git\\joelverhagen\\Azurite\\node_modules\\express\\lib\\router\\index.js:280:10)"
2023-10-26T16:10:28.671Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 error: ErrorMiddleware: Set HTTP code: 409
2023-10-26T16:10:28.671Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 error: ErrorMiddleware: Set HTTP status message: The specified container already exists.
2023-10-26T16:10:28.671Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 error: ErrorMiddleware: Set HTTP Header: x-ms-error-code=ContainerAlreadyExists
2023-10-26T16:10:28.672Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 error: ErrorMiddleware: Set HTTP Header: x-ms-request-id=97e865a9-62f3-4d6c-bfe8-488dd6c96a30
2023-10-26T16:10:28.672Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 error: ErrorMiddleware: Set content type: application/xml
2023-10-26T16:10:28.672Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 error: ErrorMiddleware: Set HTTP body: "<?xml version=\"1.0\" encoding=\"UTF-8\" standalone=\"yes\"?>\n<Error>\n  <Code>ContainerAlreadyExists</Code>\n  <Message>The specified container already exists.\nRequestId:97e865a9-62f3-4d6c-bfe8-488dd6c96a30\nTime:2023-10-26T16:10:28.656Z</Message>\n</Error>"
2023-10-26T16:10:28.674Z 97e865a9-62f3-4d6c-bfe8-488dd6c96a30 info: EndMiddleware: End response. TotalTimeInMS=38 StatusCode=409 StatusMessage=The specified container already exists. Headers={"server":"Azurite-Blob/3.27.0","x-ms-error-code":"ContainerAlreadyExists","x-ms-request-id":"97e865a9-62f3-4d6c-bfe8-488dd6c96a30","content-type":"application/xml"}
2023-10-26T16:10:28.711Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/test/foo RequestHeaders:{"host":"127.0.0.1:10000","x-ms-blob-type":"BlockBlob","x-ms-version":"2023-08-03","accept":"application/xml","x-ms-client-request-id":"34a00ca1-4a33-4849-8c15-82a1d5283e1d","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Blobs/12.18.0 (.NET 7.0.12; Microsoft Windows 10.0.22621)","x-ms-date":"Thu, 26 Oct 2023 16:10:28 GMT","authorization":"SharedKey devstoreaccount1:3yGnM1hulv7dyfAAKWVhrycVV9WisEMuzxKx46kJGDg=","content-length":"0","content-type":"application/octet-stream"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2023-10-26T16:10:28.712Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=test Blob=foo
2023-10-26T16:10:28.712Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe verbose: DispatchMiddleware: Dispatching request...
2023-10-26T16:10:28.713Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: DispatchMiddleware: Operation=BlockBlob_Upload
2023-10-26T16:10:28.713Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2023-10-26T16:10:28.713Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: PublicAccessAuthenticator:validate() Start validation against public access.
2023-10-26T16:10:28.713Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: PublicAccessAuthenticator:validate() Getting account properties...
2023-10-26T16:10:28.713Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: test, blob: foo
2023-10-26T16:10:28.713Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container test
2023-10-26T16:10:28.713Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2023-10-26T16:10:28.713Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\napplication/octet-stream\n\n\n\n\n\n\nx-ms-blob-type:BlockBlob\nx-ms-client-request-id:34a00ca1-4a33-4849-8c15-82a1d5283e1d\nx-ms-date:Thu, 26 Oct 2023 16:10:28 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2023-08-03\n/devstoreaccount1/devstoreaccount1/test/foo"
2023-10-26T16:10:28.714Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:3yGnM1hulv7dyfAAKWVhrycVV9WisEMuzxKx46kJGDg=
2023-10-26T16:10:28.714Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2023-10-26T16:10:28.714Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe verbose: DeserializerMiddleware: Start deserializing...
2023-10-26T16:10:28.714Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{},"requestId":"34a00ca1-4a33-4849-8c15-82a1d5283e1d","blobHTTPHeaders":{},"leaseAccessConditions":{},"cpkInfo":{},"cpkScopeInfo":{},"modifiedAccessConditions":{}},"contentLength":0,"version":"2023-08-03","blobType":"BlockBlob","body":"ReadableStream"}
2023-10-26T16:10:28.714Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: OperationQueue.operate() Schedule incoming job c928135d-2c6e-448f-9a5c-13eed55bb4f4
2023-10-26T16:10:28.715Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:1
2023-10-26T16:10:28.715Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:1 extentId:5292bdd3-088a-4723-8b7f-ae985c1f548e offset:0 MAX_EXTENT_SIZE:67108864 
2023-10-26T16:10:28.715Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:appendExtent() Get fd:undefined for extent:5292bdd3-088a-4723-8b7f-ae985c1f548e from cache.
2023-10-26T16:10:28.716Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:appendExtent() Open file:C:\z\Git\joelverhagen\Azurite\__blobstorage__\5292bdd3-088a-4723-8b7f-ae985c1f548e for extent:5292bdd3-088a-4723-8b7f-ae985c1f548e, get new fd:4
2023-10-26T16:10:28.716Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:appendExtent() Created write stream for fd:4
2023-10-26T16:10:28.716Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:appendExtent() Start writing to extent 5292bdd3-088a-4723-8b7f-ae985c1f548e
2023-10-26T16:10:28.716Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:streamPipe() Start piping data to write stream
2023-10-26T16:10:28.716Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:streamPipe() Readable stream triggers close event, 0 bytes piped
2023-10-26T16:10:28.716Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:streamPipe() Invoke write stream end()
2023-10-26T16:10:28.717Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:streamPipe() Writable stream triggers finish event, after 0 bytes piped. Flush data to fd:4.
2023-10-26T16:10:28.717Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:streamPipe() Readable stream triggers close event, 0 bytes piped
2023-10-26T16:10:28.720Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:streamPipe() Flush data to fd:4 successfully. Resolve streamPipe().
2023-10-26T16:10:28.721Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:appendExtent() Write finish, start updating extent metadata. extent:{"id":"5292bdd3-088a-4723-8b7f-ae985c1f548e","locationId":"Default","path":"5292bdd3-088a-4723-8b7f-ae985c1f548e","size":0,"lastModifiedInMS":1698336628721}
2023-10-26T16:10:28.721Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: FSExtentStore:appendExtent() Update extent metadata done. Resolve()
2023-10-26T16:10:28.721Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: OperationQueue.operate() Job c928135d-2c6e-448f-9a5c-13eed55bb4f4 completes callback, resolve.
2023-10-26T16:10:28.722Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:50 operations.length:0
2023-10-26T16:10:28.722Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe debug: OperationQueue:execute() return. Operation.length === 0
2023-10-26T16:10:28.723Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe verbose: SerializerMiddleware: Start serializing...
2023-10-26T16:10:28.724Z 52faa826-38bf-4eab-9ed7-caa5b85d6afe info: EndMiddleware: End response. TotalTimeInMS=13 StatusCode=201 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.27.0","etag":"\"0x1ED97DA0A39C9D0\"","last-modified":"Thu, 26 Oct 2023 16:10:28 GMT","content-md5":"1B2M2Y8AsgTpgAmY7PhCfg==","x-ms-client-request-id":"34a00ca1-4a33-4849-8c15-82a1d5283e1d","x-ms-request-id":"52faa826-38bf-4eab-9ed7-caa5b85d6afe","x-ms-version":"2023-11-03","date":"Thu, 26 Oct 2023 16:10:28 GMT","x-ms-request-server-encrypted":"true"}
2023-10-26T16:10:28.743Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: QueueStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/test RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","accept":"application/xml","x-ms-client-request-id":"2a6b74d1-672f-46c0-8d3f-a08f1c25376d","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.16.0 (.NET 7.0.12; Microsoft Windows 10.0.22621)","x-ms-date":"Thu, 26 Oct 2023 16:10:28 GMT","authorization":"SharedKey devstoreaccount1:ryniQyVLindHoouPq/8t2tieJ9DinS9Q9qbbp0tViTM=","content-length":"0"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2023-10-26T16:10:28.743Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=test Message=undefined MessageId=undefined
2023-10-26T16:10:28.743Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 verbose: DispatchMiddleware: Dispatching request...
2023-10-26T16:10:28.744Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: DispatchMiddleware: Operation=Queue_Create
2023-10-26T16:10:28.744Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2023-10-26T16:10:28.744Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2023-10-26T16:10:28.745Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:2a6b74d1-672f-46c0-8d3f-a08f1c25376d\nx-ms-date:Thu, 26 Oct 2023 16:10:28 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/test"
2023-10-26T16:10:28.745Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:ryniQyVLindHoouPq/8t2tieJ9DinS9Q9qbbp0tViTM=
2023-10-26T16:10:28.745Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2023-10-26T16:10:28.745Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 verbose: DeserializerMiddleware: Start deserializing...
2023-10-26T16:10:28.745Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{},"requestId":"2a6b74d1-672f-46c0-8d3f-a08f1c25376d"},"version":"2018-11-09"}
2023-10-26T16:10:28.746Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 verbose: SerializerMiddleware: Start serializing...
2023-10-26T16:10:28.747Z 5ab86a64-76f1-43ef-bd70-0de50d35dd84 info: EndMiddleware: End response. TotalTimeInMS=4 StatusCode=204 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.27.0","x-ms-client-request-id":"2a6b74d1-672f-46c0-8d3f-a08f1c25376d","x-ms-request-id":"5ab86a64-76f1-43ef-bd70-0de50d35dd84","x-ms-version":"2023-11-03","date":"Thu, 26 Oct 2023 16:10:28 GMT"}
2023-10-26T16:10:28.788Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: TableStorageContextMiddleware: RequestMethod=POST RequestURL=http://127.0.0.1/devstoreaccount1/Tables?$format=application%2Fjson%3Bodata%3Dminimalmetadata RequestHeaders:{"host":"127.0.0.1:10002","x-ms-version":"2020-12-06","dataserviceversion":"3.0","accept":"application/json;odata=minimalmetadata","prefer":"return-no-content","x-ms-client-request-id":"403a5731-5c7c-4dc6-b96b-eced1c0aed41","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Data.Tables/12.8.1 (.NET 7.0.12; Microsoft Windows 10.0.22621)","x-ms-date":"Thu, 26 Oct 2023 16:10:28 GMT","authorization":"SharedKeyLite devstoreaccount1:oZk39XLmQ4r0XYPdDxJIdwdQtKHOzppciXbjpQUjoVk=","content-type":"application/json;odata=nometadata","content-length":"20"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2023-10-26T16:10:28.788Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f debug: tableStorageContextMiddleware: Dispatch pattern string: /Tables
2023-10-26T16:10:28.788Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: tableStorageContextMiddleware: Account=devstoreaccount1 tableName=undefined
2023-10-26T16:10:28.788Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f verbose: DispatchMiddleware: Dispatching request...
2023-10-26T16:10:28.789Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: DispatchMiddleware: Operation=Table_Create
2023-10-26T16:10:28.789Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2023-10-26T16:10:28.789Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: TableSharedKeyLiteAuthenticator:validate() Start validation against account shared key authentication.
2023-10-26T16:10:28.789Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: TableSharedKeyLiteAuthenticator:validate() [STRING TO SIGN]:"Thu, 26 Oct 2023 16:10:28 GMT\n/devstoreaccount1/devstoreaccount1/Tables"
2023-10-26T16:10:28.789Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: TableSharedKeyLiteAuthenticator:validate() Calculated authentication header based on key1: SharedKeyLite devstoreaccount1:oZk39XLmQ4r0XYPdDxJIdwdQtKHOzppciXbjpQUjoVk=
2023-10-26T16:10:28.789Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: TableSharedKeyLiteAuthenticator:validate() Signature 1 matched.
2023-10-26T16:10:28.790Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f verbose: DeserializerMiddleware: Start deserializing...
2023-10-26T16:10:28.790Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f debug: deserialize(): Raw request body string is (removed all empty characters) {"TableName":"test"}
2023-10-26T16:10:28.791Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: HandlerMiddleware: DeserializedParameters={"options":{"queryOptions":{"format":"application/json;odata=minimalmetadata"},"requestId":"403a5731-5c7c-4dc6-b96b-eced1c0aed41","dataServiceVersion":"3.0","responsePreference":"return-no-content"},"version":"2020-12-06","tableProperties":{"tableName":"test"},"body":"ReadableStream"}
2023-10-26T16:10:28.792Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f error: ErrorMiddleware: Received a MiddlewareError, fill error information to HTTP response
2023-10-26T16:10:28.794Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f error: ErrorMiddleware: ErrorName=StorageError ErrorMessage="The table specified already exists."  ErrorHTTPStatusCode=409 ErrorHTTPStatusMessage=undefined ErrorHTTPHeaders={"x-ms-error-code":"TableAlreadyExists","x-ms-request-id":"a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f","x-ms-version":"2023-11-03"} ErrorHTTPBody="{\"odata.error\":{\"code\":\"TableAlreadyExists\",\"message\":{\"lang\":\"en-US\",\"value\":\"The table specified already exists.\\nRequestId:a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f\\nTime:2023-10-26T16:10:28.792Z\"}}}" ErrorStack="\"StorageError: The table specified already exists.\\n    at Function.getTableAlreadyExists (C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\src\\\\table\\\\errors\\\\StorageErrorFactory.ts:75:12)\\n    at LokiTableMetadataStore.checkIfTableExists (C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\src\\\\table\\\\persistence\\\\LokiTableMetadataStore.ts:773:33)\\n    at LokiTableMetadataStore.createTable (C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\src\\\\table\\\\persistence\\\\LokiTableMetadataStore.ts:116:10)\\n    at TableHandler.create (C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\src\\\\table\\\\handlers\\\\TableHandler.ts:82:30)\\n    at C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\src\\\\table\\\\generated\\\\middleware\\\\HandlerMiddlewareFactory.ts:82:10\\n    at C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\src\\\\table\\\\generated\\\\ExpressMiddlewareFactory.ts:97:57\\n    at Layer.handle [as handle_request] (C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\node_modules\\\\express\\\\lib\\\\router\\\\layer.js:95:5)\\n    at trim_prefix (C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\node_modules\\\\express\\\\lib\\\\router\\\\index.js:328:13)\\n    at C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\node_modules\\\\express\\\\lib\\\\router\\\\index.js:286:9\\n    at Function.process_params (C:\\\\z\\\\Git\\\\joelverhagen\\\\Azurite\\\\node_modules\\\\express\\\\lib\\\\router\\\\index.js:346:12)\""
2023-10-26T16:10:28.794Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f error: ErrorMiddleware: Set HTTP code: 409
2023-10-26T16:10:28.794Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f error: ErrorMiddleware: Set HTTP Header: x-ms-error-code=TableAlreadyExists
2023-10-26T16:10:28.795Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f error: ErrorMiddleware: Set HTTP Header: x-ms-request-id=a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f
2023-10-26T16:10:28.795Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f error: ErrorMiddleware: Set HTTP Header: x-ms-version=2023-11-03
2023-10-26T16:10:28.795Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f error: ErrorMiddleware: Set content type: application/json;odata=minimalmetadata;streaming=true;charset=utf-8
2023-10-26T16:10:28.795Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f error: ErrorMiddleware: Set HTTP body: "{\"odata.error\":{\"code\":\"TableAlreadyExists\",\"message\":{\"lang\":\"en-US\",\"value\":\"The table specified already exists.\\nRequestId:a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f\\nTime:2023-10-26T16:10:28.792Z\"}}}"
2023-10-26T16:10:28.795Z a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f info: EndMiddleware: End response. TotalTimeInMS=7 StatusCode=409 StatusMessage=Conflict Headers={"server":"Azurite-Table/3.27.0","x-ms-error-code":"TableAlreadyExists","x-ms-request-id":"a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f","x-ms-version":"2023-11-03","content-type":"application/json;odata=minimalmetadata;streaming=true;charset=utf-8"}

Repro app:

using System.Net.Http.Headers;
using Azure.Core.Pipeline;
using Azure.Data.Tables;
using Azure.Storage.Blobs;
using Azure.Storage.Queues;

var connectionString = "UseDevelopmentStorage=true";
// var connectionString = "DefaultEndpointsProtocol=https;AccountName=REDACTED;AccountKey=REDACTED;EndpointSuffix=core.windows.net";

var pipeline = new HttpClientTransport(new TestHandler { InnerHandler = new HttpClientHandler() });

var blobServiceClient = new BlobServiceClient(connectionString, new BlobClientOptions { Transport = pipeline });
var containerClient = blobServiceClient.GetBlobContainerClient("test");
await containerClient.CreateIfNotExistsAsync();
var blobClient = containerClient.GetBlobClient("foo");
await blobClient.UploadAsync(new BinaryData(Array.Empty<byte>()), overwrite: true);

Console.WriteLine(new string('-', 80));

var queueServiceClient = new QueueServiceClient(connectionString, new QueueClientOptions { Transport = pipeline });
var queueClient = queueServiceClient.GetQueueClient("test");
await queueClient.CreateIfNotExistsAsync();

Console.WriteLine(new string('-', 80));

var tableServiceClient = new TableServiceClient(connectionString, new TableClientOptions { Transport = pipeline });
var tableClient = tableServiceClient.GetTableClient("test");
await tableClient.CreateIfNotExistsAsync();

public class TestHandler : DelegatingHandler
{
    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        Console.WriteLine($"> {request.Method} {request.RequestUri!.PathAndQuery}");
        PrintHeaders("x-ms-request-id", request.Headers);
        PrintHeaders("x-ms-client-request-id", request.Headers);

        var response = await base.SendAsync(request, cancellationToken);

        Console.WriteLine($"< {(int)response.StatusCode} {response.ReasonPhrase}");
        PrintHeaders("x-ms-request-id", response.Headers);
        PrintHeaders("x-ms-client-request-id", response.Headers);
        Console.WriteLine();

        return response;
    }

    private static void PrintHeaders(string header, HttpHeaders headers)
    {
        if (headers.TryGetValues(header, out var values))
        {
            foreach (var value in values)
            {
                Console.WriteLine($"  {header}: {value}");
            }
        }
    }
}

Output from Azure Storage (good):

> PUT /test?restype=container
  x-ms-client-request-id: b293187f-9170-49e5-bc69-29d143bd1ef8
< 409 The specified container already exists.
  x-ms-request-id: acfa87f5-e01e-0031-0926-08d534000000
  x-ms-client-request-id: b293187f-9170-49e5-bc69-29d143bd1ef8

> PUT /test/foo
  x-ms-client-request-id: 0218ed33-2fb3-467a-b349-41e326d27b1e
< 201 Created
  x-ms-request-id: acfa8829-e01e-0031-3926-08d534000000
  x-ms-client-request-id: 0218ed33-2fb3-467a-b349-41e326d27b1e

--------------------------------------------------------------------------------
> PUT /test
  x-ms-client-request-id: a9544a98-78ea-4534-a47b-5bf750529a02
< 204 No Content
  x-ms-request-id: 0a49a372-1003-00a3-7e26-0851e2000000

--------------------------------------------------------------------------------
> POST /Tables?$format=application%2Fjson%3Bodata%3Dminimalmetadata
  x-ms-client-request-id: d5f261b0-8ac4-46a3-ac17-cade9e1c4c6f
< 409 Conflict
  x-ms-request-id: a0be80fd-2002-0063-2926-08a9dc000000
  x-ms-client-request-id: d5f261b0-8ac4-46a3-ac17-cade9e1c4c6f

Output from Azurite (bad -- missing x-ms-client-request-id on some responses)

> PUT /devstoreaccount1/test?restype=container
  x-ms-client-request-id: 5cc894f7-cde1-49cd-b4d1-5016fcc655cc
< 409 The specified container already exists.
  x-ms-request-id: 97e865a9-62f3-4d6c-bfe8-488dd6c96a30

> PUT /devstoreaccount1/test/foo
  x-ms-client-request-id: 34a00ca1-4a33-4849-8c15-82a1d5283e1d
< 201 Created
  x-ms-request-id: 52faa826-38bf-4eab-9ed7-caa5b85d6afe
  x-ms-client-request-id: 34a00ca1-4a33-4849-8c15-82a1d5283e1d

--------------------------------------------------------------------------------
> PUT /devstoreaccount1/test
  x-ms-client-request-id: 2a6b74d1-672f-46c0-8d3f-a08f1c25376d
< 204 No Content
  x-ms-request-id: 5ab86a64-76f1-43ef-bd70-0de50d35dd84
  x-ms-client-request-id: 2a6b74d1-672f-46c0-8d3f-a08f1c25376d

--------------------------------------------------------------------------------
> POST /devstoreaccount1/Tables?$format=application%2Fjson%3Bodata%3Dminimalmetadata
  x-ms-client-request-id: 403a5731-5c7c-4dc6-b96b-eced1c0aed41
< 409 Conflict
  x-ms-request-id: a0f4a616-4e8b-4dcd-ab2e-3c148e307c1f

Have you found a mitigation/solution?

blueww commented 1 year ago

@joelverhagen

Thanks for reporting this issue! This should be caused by the Azurite error definition doesn't include client request ID, like getContainerAlreadyExists . To fix this, we need add "x-ms-request-id" into the base class StorageError , and pass the client request ID from request to the constructor function of StorageError.

As we are working on some other features and PR reviews, this might won't be out priority in the recent future. It would be great if you can raise a PR to fix it! (There might will be a lot of code change as there are so many API/error need change.)

udlose commented 1 month ago

any update on this?

blueww commented 1 month ago

@udlose

Azurite welcome contribution! It would be great if you could raise a Pr to fix this.

The general idea to fix this is already shared above. Feel free to raise if you have any detail questions.