Error Message 500. Request failed to complete in 15000ms
- Dominant language
- TypeScript
- Stars
- 2.3k
- Forks
- 393
- Avg merge
- 1d 20h
- Merged PRs (30d)
- 36
Description
### Which service(blob, file, queue, table) does this issue concern?
Blob
### Which version of the Azurite was used?
3.14.0
### Where do you get Azurite? (npm, DockerHub, NuGet, Visual Studio Code Extension)
Github
### What problem was encountered?
As part of our automation tests. The Azurite is getting in high usage (Around 10-15 requests per second). some of the requests return with HTTP 500 errors.
### Steps to reproduce the issue?
Send load of requests in a short time.
### Log example from debug.log:
```
2021-11-02T15:43:21.361Z e51892db-d397-4e58-8978-74c4c86c2838 info: BlobStorageContextMiddleware: RequestMethod=PUT RequestURL=http://azurite-service.qa.svc.cluster.local/devstoreaccount1/qac/propagation_assortments%2F18208_d2839409-a6f1-44a3-992f-fa9102819b70?comp=properties RequestHeaders:{"host":"azurite-service.qa.svc.cluster.local:10000","x-ms-version":"2020-02-10","x-ms-blob-content-type":"application/json","x-ms-blob-content-encoding":"gzip","x-ms-client-request-id":"42a3d8dd-da27-4b56-b6d5-581d5c709abc","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Blobs/12.7.0 (.NET Core 3.1.20; Linux 5.4.0-88-generic #99-Ubuntu SMP Thu Sep 23 17:29:00 UTC 2021)","x-ms-date":"Tue, 02 Nov 2021 15:43:21 GMT","authorization":"SharedKey devstoreaccount1:KE9nAPOalOZrzD480tvVfBKUYfLy4MCbvad/Jkgv4Gw=","traceparent":"00-7cd69414f413694997525ee7d74109a6-49bb3c623983634b-00","uber-trace-id":"4819fc6a0c629a34%3A860fb0e737460e0d%3Aa9258b41d44499f7%3A0","content-length":"0"} ClientIP=10.1.142.7 Protocol=http HTTPVersion=1.1
2021-11-02T15:43:21.362Z e51892db-d397-4e58-8978-74c4c86c2838 info: BlobStorageContextMiddleware: Account=devstoreaccount1 Container=qac Blob=propagation_assortments/18208_d2839409-a6f1-44a3-992f-fa9102819b70
2021-11-02T15:43:21.362Z e51892db-d397-4e58-8978-74c4c86c2838 verbose: DispatchMiddleware: Dispatching request...
2021-11-02T15:43:21.362Z e51892db-d397-4e58-8978-74c4c86c2838 info: DispatchMiddleware: Operation=Blob_SetHTTPHeaders
2021-11-02T15:43:21.362Z e51892db-d397-4e58-8978-74c4c86c2838 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2021-11-02T15:43:21.362Z e51892db-d397-4e58-8978-74c4c86c2838 info: PublicAccessAuthenticator:validate() Start validation against public access.
2021-11-02T15:43:21.362Z e51892db-d397-4e58-8978-74c4c86c2838 debug: PublicAccessAuthenticator:validate() Getting account properties...
2021-11-02T15:43:21.362Z e51892db-d397-4e58-8978-74c4c86c2838 debug: PublicAccessAuthenticator:validate() Retrieved account name from context: devstoreaccount1, container: qac, blob: propagation_assortments/18208_d2839409-a6f1-44a3-992f-fa9102819b70
2021-11-02T15:43:21.399Z e51892db-d397-4e58-8978-74c4c86c2838 debug: PublicAccessAuthenticator:validate() Skip public access authentication. Cannot get public access type for container qac
2021-11-02T15:43:21.399Z e51892db-d397-4e58-8978-74c4c86c2838 info: BlobSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2021-11-02T15:43:21.400Z e51892db-d397-4e58-8978-74c4c86c2838 info: BlobSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\n\n\n\n\n\n\n\nx-ms-blob-content-encoding:gzip\nx-ms-blob-content-type:application/json\nx-ms-client-request-id:42a3d8dd-da27-4b56-b6d5-581d5c709abc\nx-ms-date:Tue, 02 Nov 2021 15:43:21 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2020-02-10\n/devstoreaccount1/devstoreaccount1/qac/propagation_assortments%2F18208_d2839409-a6f1-44a3-992f-fa9102819b70\ncomp:properties"
2021-11-02T15:43:21.400Z e51892db-d397-4e58-8978-74c4c86c2838 info: BlobSharedKeyAuthenticator:validate() Calculated authentication header based on key1: SharedKey devstoreaccount1:KEY
2021-11-02T15:43:21.400Z e51892db-d397-4e58-8978-74c4c86c2838 info: BlobSharedKeyAuthenticator:validate() Signature 1 matched.
2021-11-02T15:43:21.400Z e51892db-d397-4e58-8978-74c4c86c2838 verbose: DeserializerMiddleware: Start deserializing...
2021-11-02T15:43:21.400Z e51892db-d397-4e58-8978-74c4c86c2838 info: HandlerMiddleware: DeserializedParameters={"options":{"requestId":"42a3d8dd-da27-4b56-b6d5-581d5c709abc","blobHTTPHeaders":{"blobContentType":"application/json","blobContentEncoding":"gzip"},"leaseAccessConditions":{},"modifiedAccessConditions":{}},"comp":"properties","version":"2020-02-10"}
2021-11-02T15:43:36.478Z e51892db-d397-4e58-8978-74c4c86c2838 error: ErrorMiddleware: Received an error, fill error information to HTTP response
2021-11-02T15:43:36.478Z e51892db-d397-4e58-8978-74c4c86c2838 error: ErrorMiddleware: ErrorName=SequelizeDatabaseError ErrorMessage=Timeout: Request failed to complete in 15000ms ErrorStack="SequelizeDatabaseError: Timeout: Request failed to complete in 15000ms\n at Query.formatError (/opt/azurite/node_modules/sequelize/lib/dialects/mssql/query.js:314:12)\n at Query._run (/opt/azurite/node_modules/sequelize/lib/dialects/mssql/query.js:93:18)\n at runMicrotasks ()\n at processTicksAndRejections (internal/process/task_queues.js:95:5)\n at async /opt/azurite/node_modules/sequelize/lib/sequelize.js:619:16\n at async MSSqlQueryInterface.bulkUpdate (/opt/azurite/node_modules/sequelize/lib/dialects/abstract/query-interface.js:882:12)\n at async Function.update (/opt/azurite/node_modules/sequelize/lib/model.js:3188:28)\n at async /opt/azurite/dist/src/blob/persistence/SqlBlobMetadataStore.js:1360:13\n at async /opt/azurite/node_modules/sequelize/lib/sequelize.js:1090:24\n at async BlobHandler.setHTTPHeaders (/opt/azurite/dist/src/blob/handlers/BlobHandler.js:156:19)"
2021-11-02T15:43:36.478Z e51892db-d397-4e58-8978-74c4c86c2838 error: ErrorMiddleware: Set HTTP code: 500
2021-11-02T15:43:36.478Z e51892db-d397-4e58-8978-74c4c86c2838 info: EndMiddleware: End response. TotalTimeInMS=15117 StatusCode=500 StatusMessage=undefined Headers={"server":"Azurite-Blob/3.14.0"}
```
### Notes:
Azurite is running on a single pod.
We are using an external DB located in the same network as the Azurite.
The issue doesn't happen when running the requests separately.
There is no resource usage issue with withe pod/cluster.
Contributor guide
No contributing guide indexed for this repository
Assessment
This issue has not been assessed yet.