Azurite
Azurite copied to clipboard
Published
20 hours ago •
Azure
Azure
500 Error: XmlException: Root element is missing
Which service(blob, file, queue, table) does this issue concern?
Queue
Which version of the Azurite was used?
3.16.0
Where do you get Azurite? (npm, DockerHub, NuGet, Visual Studio Code Extension)
Visual Studio 2022 17.2.0 built-in
What's the Node.js version?
14.17.3
What problem was encountered?
While attempting to run QueueClient.SendMessageAsync(b64), the request hangs for ~10 seconds and then throws 500 Internal Server Error.
var created = _queueClient.CreateIfNotExists();
if (_queueClient.Exists())
{
if (created != null)
{
_logger.LogInformation($"Queue created: '{_queueClient.Name}'");
}
else
{
_logger.LogInformation($"Queue found: '{_queueClient.Name}'");
}
// queue requires a base64 string
var plainTextBytes = System.Text.Encoding.UTF8.GetBytes(reportId);
var b64 = Convert.ToBase64String(plainTextBytes);
await _queueClient.SendMessageAsync(b64);
}
else
{
_logger.LogError($"Unable to find or create queue: '{_queueClient.Name}'");
return;
}
The exception that I recieve is
System.Xml.XmlException: Root element is missing.
at System.Xml.XmlTextReaderImpl.Throw(Exception e)
at System.Xml.XmlTextReaderImpl.ParseDocumentContent()
at System.Xml.Linq.XDocument.Load(XmlReader reader, LoadOptions options)
at System.Xml.Linq.XDocument.Load(Stream stream, LoadOptions options)
at Azure.Storage.Queues.QueueRestClient.Messages.EnqueueAsync_CreateResponse(ClientDiagnostics clientDiagnostics, Response response)
at Azure.Storage.Queues.QueueRestClient.Messages.EnqueueAsync(ClientDiagnostics clientDiagnostics, HttpPipeline pipeline, Uri resourceUri, QueueSendMessage message, String version, Nullable`1 visibilitytimeout, Nullable`1 messageTimeToLive, Nullable`1 timeout, String requestId, Boolean async, String operationName, CancellationToken cancellationToken)
at Azure.Storage.Queues.QueueClient.SendMessageInternal(String messageText, Nullable`1 visibilityTimeout, Nullable`1 timeToLive, Boolean async, CancellationToken cancellationToken)
at Azure.Storage.Queues.QueueClient.SendMessageAsync(String messageText, Nullable`1 visibilityTimeout, Nullable`1 timeToLive, CancellationToken cancellationToken)
at Azure.Storage.Queues.QueueClient.SendMessageAsync(String messageText)
My Queue folder is currently empty but it has definitely been recieving messages a few days ago, so it seems like something deleted the queue file. The azurite_db_queue.json still has a reference to the queue I'm trying to write to.
I'm not sure if this is related, but I also still regularly encounter this issue: https://github.com/Azure/Azurite/issues/1492
Steps to reproduce the issue?
Intermittent
Debug logs
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=messages MessageId=undefined
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 verbose: DispatchMiddleware: Dispatching request...
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: DispatchMiddleware: Operation=Messages_Enqueue
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"POST\n\n\n88\n\napplication/xml\n\n\n\n\n\n\nx-ms-client-request-id:f6f23474-5cbc-4b77-bb53-0d44cea0941c\nx-ms-date:Tue, 20 Sep 2022 00:39:40 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs/messages"
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:+BhqAybFO7EW/eqMnRSfR1l8TGtfk+IETmEp7qnzWd4=
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 debug: deserialize(): Raw request body string is (removed all empty characters) <QueueMessage><MessageText>bXhyZnUwR3VRa0tZWFlQdVc1SUctUQ==</MessageText></QueueMessage>
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: HandlerMiddleware: DeserializedParameters={"options":{"requestId":"f6f23474-5cbc-4b77-bb53-0d44cea0941c"},"version":"2018-11-09","queueMessage":{"messageText":"bXhyZnUwR3VRa0tZWFlQdVc1SUctUQ=="},"body":"ReadableStream"}
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 debug: OperationQueue.operate() Schedule incoming job 7e2926a6-5ac5-44ff-a314-4d14e1426b5b
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:1
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:0 extentId:c297fef4-6975-48e5-8ec0-d52a8d302e1b offset:0 MAX_EXTENT_SIZE:67108864
2022-09-20T00:39:40.842Z b42cb624-6bb3-4582-ad42-44bd425f7f28 debug: FSExtentStore:appendExtent() Get fd:undefined for extent:c297fef4-6975-48e5-8ec0-d52a8d302e1b from cache.
2022-09-20T00:39:40.843Z b42cb624-6bb3-4582-ad42-44bd425f7f28 debug: OperationQueue.operate() Job 7e2926a6-5ac5-44ff-a314-4d14e1426b5b error, reject.
2022-09-20T00:39:40.843Z b42cb624-6bb3-4582-ad42-44bd425f7f28 error: ErrorMiddleware: Received an error, fill error information to HTTP response
2022-09-20T00:39:40.843Z b42cb624-6bb3-4582-ad42-44bd425f7f28 error: ErrorMiddleware: ErrorName=Error ErrorMessage=ENOENT: no such file or directory, open 'C:\Users\***\AppData\Local\Temp\Azurite\__queuestorage__\c297fef4-6975-48e5-8ec0-d52a8d302e1b' ErrorStack="Error: ENOENT: no such file or directory, open 'C:\\Users\\***\\AppData\\Local\\Temp\\Azurite\\__queuestorage__\\c297fef4-6975-48e5-8ec0-d52a8d302e1b'"
2022-09-20T00:39:40.843Z b42cb624-6bb3-4582-ad42-44bd425f7f28 error: ErrorMiddleware: Set HTTP code: 500
2022-09-20T00:39:40.843Z b42cb624-6bb3-4582-ad42-44bd425f7f28 info: EndMiddleware: End response. TotalTimeInMS=2 StatusCode=500 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.16.0"}
2022-09-20T00:39:40.843Z b42cb624-6bb3-4582-ad42-44bd425f7f28 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:0
2022-09-20T00:39:40.843Z b42cb624-6bb3-4582-ad42-44bd425f7f28 debug: OperationQueue:execute() return. Operation.length === 0
Have you found a mitigation/solution?
Restarting my PC fixed the queue issue, but it doesn't work for the issue when it happens with Blobs.
@LukeBolly We see the error is "FSExtentStore:appendExtent() Get fd:undefined for extent:c297fef4-6975-48e5-8ec0-d52a8d302e1b from cache." It's possible local persisted file doesn't exist or can't be access. Somewhere before puts a undefined into fd cache.
Would you please share the full azurite debug log from Azurite start to the error happen. Or at least the debug log for all requests include the extent Id "c297fef4-6975-48e5-8ec0-d52a8d302e1b", so we can see why it's undefined.
BTW, it might be an access issue. Do you run Azurite with Admin access, or will be issue repro if you run it with admin access? And do you switch different users to start Azurite and using same workspace?
Searching for "c297fef4-6975-48e5-8ec0-d52a8d302e1b" returns 120 hits, all within a 40 minute period from when I turned on my PC today to when I restarted it, and the error went away. All the logs appear to be the same error so here is the very first one:
2022-09-20T00:18:44.960Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: QueueStorageContextMiddleware: RequestMethod=POST RequestURL=http://127.0.0.1/devstoreaccount1/recording-import-jobs/messages RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","x-ms-client-request-id":"6d863357-ed82-410c-bb82-2ff188f11a9e","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.4.2 (.NET 5.0.17; Microsoft Windows 10.0.19043)","x-ms-date":"Tue, 20 Sep 2022 00:18:44 GMT","authorization":"SharedKey devstoreaccount1:v2Stp3yXJ8TrnKl8Pt5d/qvZJlALYNKEGYOikyaA8ps=","traceparent":"00-9ff7a244e2c5094eb780712f28856d89-03fd381835d7a84b-00","content-type":"application/xml","content-length":"88"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-20T00:18:44.960Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=messages MessageId=undefined
2022-09-20T00:18:44.960Z 6f460455-c46f-41ca-b6be-f9669c227ff2 verbose: DispatchMiddleware: Dispatching request...
2022-09-20T00:18:44.960Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: DispatchMiddleware: Operation=Messages_Enqueue
2022-09-20T00:18:44.960Z 6f460455-c46f-41ca-b6be-f9669c227ff2 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T00:18:44.960Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T00:18:44.961Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"POST\n\n\n88\n\napplication/xml\n\n\n\n\n\n\nx-ms-client-request-id:6d863357-ed82-410c-bb82-2ff188f11a9e\nx-ms-date:Tue, 20 Sep 2022 00:18:44 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs/messages"
2022-09-20T00:18:44.961Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:v2Stp3yXJ8TrnKl8Pt5d/qvZJlALYNKEGYOikyaA8ps=
2022-09-20T00:18:44.961Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T00:18:44.961Z 6f460455-c46f-41ca-b6be-f9669c227ff2 verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T00:18:44.962Z 6f460455-c46f-41ca-b6be-f9669c227ff2 debug: deserialize(): Raw request body string is (removed all empty characters) <QueueMessage><MessageText>OWdTYlZTMWhURXlCUFZYVWdUb0lMUQ==</MessageText></QueueMessage>
2022-09-20T00:18:44.963Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: HandlerMiddleware: DeserializedParameters={"options":{"requestId":"6d863357-ed82-410c-bb82-2ff188f11a9e"},"version":"2018-11-09","queueMessage":{"messageText":"OWdTYlZTMWhURXlCUFZYVWdUb0lMUQ=="},"body":"ReadableStream"}
2022-09-20T00:18:44.964Z 6f460455-c46f-41ca-b6be-f9669c227ff2 debug: OperationQueue.operate() Schedule incoming job bb4716c6-2de4-41f0-a863-0ac2bdfa5d66
2022-09-20T00:18:44.964Z 6f460455-c46f-41ca-b6be-f9669c227ff2 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:1
2022-09-20T00:18:44.964Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:0 extentId:c297fef4-6975-48e5-8ec0-d52a8d302e1b offset:0 MAX_EXTENT_SIZE:67108864
2022-09-20T00:18:44.964Z 6f460455-c46f-41ca-b6be-f9669c227ff2 debug: FSExtentStore:appendExtent() Get fd:undefined for extent:c297fef4-6975-48e5-8ec0-d52a8d302e1b from cache.
2022-09-20T00:18:44.964Z 6f460455-c46f-41ca-b6be-f9669c227ff2 debug: OperationQueue.operate() Job bb4716c6-2de4-41f0-a863-0ac2bdfa5d66 error, reject.
2022-09-20T00:18:44.965Z 6f460455-c46f-41ca-b6be-f9669c227ff2 error: ErrorMiddleware: Received an error, fill error information to HTTP response
2022-09-20T00:18:44.965Z 6f460455-c46f-41ca-b6be-f9669c227ff2 error: ErrorMiddleware: ErrorName=Error ErrorMessage=ENOENT: no such file or directory, open 'C:\Users\***\AppData\Local\Temp\Azurite\__queuestorage__\c297fef4-6975-48e5-8ec0-d52a8d302e1b' ErrorStack="Error: ENOENT: no such file or directory, open 'C:\\Users\\***\\AppData\\Local\\Temp\\Azurite\\__queuestorage__\\c297fef4-6975-48e5-8ec0-d52a8d302e1b'"
2022-09-20T00:18:44.965Z 6f460455-c46f-41ca-b6be-f9669c227ff2 error: ErrorMiddleware: Set HTTP code: 500
2022-09-20T00:18:44.965Z 6f460455-c46f-41ca-b6be-f9669c227ff2 info: EndMiddleware: End response. TotalTimeInMS=5 StatusCode=500 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.16.0"}
2022-09-20T00:18:44.965Z 6f460455-c46f-41ca-b6be-f9669c227ff2 debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:0
2022-09-20T00:18:44.966Z 6f460455-c46f-41ca-b6be-f9669c227ff2 debug: OperationQueue:execute() return. Operation.length === 0
2022-09-20T00:18:45.920Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: QueueStorageContextMiddleware: RequestMethod=POST RequestURL=http://127.0.0.1/devstoreaccount1/recording-import-jobs/messages RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","x-ms-client-request-id":"6d863357-ed82-410c-bb82-2ff188f11a9e","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.4.2 (.NET 5.0.17; Microsoft Windows 10.0.19043)","x-ms-date":"Tue, 20 Sep 2022 00:18:45 GMT","authorization":"SharedKey devstoreaccount1:QJngFJunTNLcVTUufyNDDPnZrBnXmc/F7WEi/hnlC7Y=","traceparent":"00-9ff7a244e2c5094eb780712f28856d89-03fd381835d7a84b-00","content-type":"application/xml","content-length":"88"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-20T00:18:45.920Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=messages MessageId=undefined
2022-09-20T00:18:45.920Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c verbose: DispatchMiddleware: Dispatching request...
2022-09-20T00:18:45.920Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: DispatchMiddleware: Operation=Messages_Enqueue
2022-09-20T00:18:45.920Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T00:18:45.920Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T00:18:45.920Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"POST\n\n\n88\n\napplication/xml\n\n\n\n\n\n\nx-ms-client-request-id:6d863357-ed82-410c-bb82-2ff188f11a9e\nx-ms-date:Tue, 20 Sep 2022 00:18:45 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs/messages"
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:QJngFJunTNLcVTUufyNDDPnZrBnXmc/F7WEi/hnlC7Y=
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c debug: deserialize(): Raw request body string is (removed all empty characters) <QueueMessage><MessageText>OWdTYlZTMWhURXlCUFZYVWdUb0lMUQ==</MessageText></QueueMessage>
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: HandlerMiddleware: DeserializedParameters={"options":{"requestId":"6d863357-ed82-410c-bb82-2ff188f11a9e"},"version":"2018-11-09","queueMessage":{"messageText":"OWdTYlZTMWhURXlCUFZYVWdUb0lMUQ=="},"body":"ReadableStream"}
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c debug: OperationQueue.operate() Schedule incoming job 082175fc-e5c4-415b-9d82-8c429da45f31
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:1
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:0 extentId:c297fef4-6975-48e5-8ec0-d52a8d302e1b offset:0 MAX_EXTENT_SIZE:67108864
2022-09-20T00:18:45.921Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c debug: FSExtentStore:appendExtent() Get fd:undefined for extent:c297fef4-6975-48e5-8ec0-d52a8d302e1b from cache.
2022-09-20T00:18:45.922Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c debug: OperationQueue.operate() Job 082175fc-e5c4-415b-9d82-8c429da45f31 error, reject.
2022-09-20T00:18:45.922Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c error: ErrorMiddleware: Received an error, fill error information to HTTP response
2022-09-20T00:18:45.922Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c error: ErrorMiddleware: ErrorName=Error ErrorMessage=ENOENT: no such file or directory, open 'C:\Users\***\AppData\Local\Temp\Azurite\__queuestorage__\c297fef4-6975-48e5-8ec0-d52a8d302e1b' ErrorStack="Error: ENOENT: no such file or directory, open 'C:\\Users\\***\\AppData\\Local\\Temp\\Azurite\\__queuestorage__\\c297fef4-6975-48e5-8ec0-d52a8d302e1b'"
2022-09-20T00:18:45.922Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c error: ErrorMiddleware: Set HTTP code: 500
2022-09-20T00:18:45.922Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c info: EndMiddleware: End response. TotalTimeInMS=2 StatusCode=500 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.16.0"}
2022-09-20T00:18:45.922Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:0
2022-09-20T00:18:45.922Z d7f6dbb3-0bce-466f-bc5e-ded285616d5c debug: OperationQueue:execute() return. Operation.length === 0
And no I only have one user account (I'm on Windows if that helps), so all I did today was turn on PC => queue broken, restart => queue fixed
@LukeBolly
Thanks for the reply!
For the "queue fixed", do you mean the queue request works without re-create the queue, or you mean it works on create queue then send request to the queue? Ask this since we would like to get: whether the issue happens on Create or Get the queue (write or read the disk).
As the issue disappear after restart the machine, it might can be the file is locked by other process. If the issue happens, if you close/reopen Visual studio, can it be fixed? And please let us know if you can or can't repro it by run it with admin access.
It looks we can't repro this issue on our local machine, by run it 1-2 days. We might would need more time to investigate it.
I'm not 100% sure whether the queue was re-created or not because I call CreateIfNotExists() before attempting to write to the queue.
Here is the last attempt to write to the queue while it was failing before I restarted: (PUT for the CreateIfNotExists, GET to get the queue, and POST to post a message)
2022-09-20T00:39:28.463Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: QueueStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/recording-import-jobs RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","x-ms-client-request-id":"73a81446-fd1c-4c63-85a9-339e9edc6782","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.4.2 (.NET 5.0.17; Microsoft Windows 10.0.19043)","x-ms-date":"Tue, 20 Sep 2022 00:39:28 GMT","authorization":"SharedKey devstoreaccount1:l3ggOBwqsUEekkzSe2fiY9s111zhLkmKx4kMCVRuMJM=","traceparent":"00-cacbf14e8d4b924bbc4d82e05c4f9986-cb7fa79b8b2a3c4c-00","content-length":"0"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-20T00:39:28.463Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=undefined MessageId=undefined
2022-09-20T00:39:28.463Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 verbose: DispatchMiddleware: Dispatching request...
2022-09-20T00:39:28.463Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: DispatchMiddleware: Operation=Queue_Create
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:73a81446-fd1c-4c63-85a9-339e9edc6782\nx-ms-date:Tue, 20 Sep 2022 00:39:28 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs"
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:l3ggOBwqsUEekkzSe2fiY9s111zhLkmKx4kMCVRuMJM=
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{},"requestId":"73a81446-fd1c-4c63-85a9-339e9edc6782"},"version":"2018-11-09"}
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 verbose: SerializerMiddleware: Start serializing...
2022-09-20T00:39:28.464Z 1958c1b2-3e7e-4c75-8415-819e4783cbe0 info: EndMiddleware: End response. TotalTimeInMS=1 StatusCode=204 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.16.0","x-ms-client-request-id":"73a81446-fd1c-4c63-85a9-339e9edc6782","x-ms-request-id":"1958c1b2-3e7e-4c75-8415-819e4783cbe0","x-ms-version":"2021-04-10","date":"Tue, 20 Sep 2022 00:39:28 GMT"}
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: QueueStorageContextMiddleware: RequestMethod=GET RequestURL=http://127.0.0.1/devstoreaccount1/recording-import-jobs?comp=metadata RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","x-ms-client-request-id":"9e202165-13f4-4e3d-8241-3501eb207cd7","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.4.2 (.NET 5.0.17; Microsoft Windows 10.0.19043)","x-ms-date":"Tue, 20 Sep 2022 00:39:28 GMT","authorization":"SharedKey devstoreaccount1:c3MoGBN783FCajiJPLsWtLS58+6wWsYDEj3acrZ/ap0=","traceparent":"00-cacbf14e8d4b924bbc4d82e05c4f9986-cb7fa79b8b2a3c4c-00"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=undefined MessageId=undefined
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c verbose: DispatchMiddleware: Dispatching request...
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: DispatchMiddleware: Operation=Queue_GetProperties
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"GET\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:9e202165-13f4-4e3d-8241-3501eb207cd7\nx-ms-date:Tue, 20 Sep 2022 00:39:28 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs\ncomp:metadata"
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:c3MoGBN783FCajiJPLsWtLS58+6wWsYDEj3acrZ/ap0=
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: HandlerMiddleware: DeserializedParameters={"options":{"requestId":"9e202165-13f4-4e3d-8241-3501eb207cd7"},"comp":"metadata","version":"2018-11-09"}
2022-09-20T00:39:28.475Z e96178c6-0c7e-4037-bc61-f58f457cf98c verbose: SerializerMiddleware: Start serializing...
2022-09-20T00:39:28.476Z e96178c6-0c7e-4037-bc61-f58f457cf98c info: EndMiddleware: End response. TotalTimeInMS=1 StatusCode=200 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.16.0","x-ms-client-request-id":"9e202165-13f4-4e3d-8241-3501eb207cd7","x-ms-approximate-messages-count":"0","x-ms-request-id":"e96178c6-0c7e-4037-bc61-f58f457cf98c","x-ms-version":"2021-04-10","date":"Tue, 20 Sep 2022 00:39:28 GMT"}
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: QueueStorageContextMiddleware: RequestMethod=POST RequestURL=http://127.0.0.1/devstoreaccount1/recording-import-jobs/messages RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","x-ms-client-request-id":"f6f23474-5cbc-4b77-bb53-0d44cea0941c","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.4.2 (.NET 5.0.17; Microsoft Windows 10.0.19043)","x-ms-date":"Tue, 20 Sep 2022 00:39:28 GMT","authorization":"SharedKey devstoreaccount1:m+reKzP7T24BFMOOJK7e7UmFozf+0axuWrTieVRk2Vo=","traceparent":"00-cacbf14e8d4b924bbc4d82e05c4f9986-cb7fa79b8b2a3c4c-00","content-type":"application/xml","content-length":"88"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=messages MessageId=undefined
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d verbose: DispatchMiddleware: Dispatching request...
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: DispatchMiddleware: Operation=Messages_Enqueue
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"POST\n\n\n88\n\napplication/xml\n\n\n\n\n\n\nx-ms-client-request-id:f6f23474-5cbc-4b77-bb53-0d44cea0941c\nx-ms-date:Tue, 20 Sep 2022 00:39:28 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs/messages"
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:m+reKzP7T24BFMOOJK7e7UmFozf+0axuWrTieVRk2Vo=
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T00:39:28.487Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T00:39:28.488Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d debug: deserialize(): Raw request body string is (removed all empty characters) <QueueMessage><MessageText>bXhyZnUwR3VRa0tZWFlQdVc1SUctUQ==</MessageText></QueueMessage>
2022-09-20T00:39:28.488Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: HandlerMiddleware: DeserializedParameters={"options":{"requestId":"f6f23474-5cbc-4b77-bb53-0d44cea0941c"},"version":"2018-11-09","queueMessage":{"messageText":"bXhyZnUwR3VRa0tZWFlQdVc1SUctUQ=="},"body":"ReadableStream"}
2022-09-20T00:39:28.489Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d debug: OperationQueue.operate() Schedule incoming job 93f78261-130b-4e79-bb0c-6b229e7fb82e
2022-09-20T00:39:28.489Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:1
2022-09-20T00:39:28.489Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:0 extentId:c297fef4-6975-48e5-8ec0-d52a8d302e1b offset:0 MAX_EXTENT_SIZE:67108864
2022-09-20T00:39:28.489Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d debug: FSExtentStore:appendExtent() Get fd:undefined for extent:c297fef4-6975-48e5-8ec0-d52a8d302e1b from cache.
2022-09-20T00:39:28.489Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d debug: OperationQueue.operate() Job 93f78261-130b-4e79-bb0c-6b229e7fb82e error, reject.
2022-09-20T00:39:28.490Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d error: ErrorMiddleware: Received an error, fill error information to HTTP response
2022-09-20T00:39:28.490Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d error: ErrorMiddleware: ErrorName=Error ErrorMessage=ENOENT: no such file or directory, open 'C:\Users\***\AppData\Local\Temp\Azurite\__queuestorage__\c297fef4-6975-48e5-8ec0-d52a8d302e1b' ErrorStack="Error: ENOENT: no such file or directory, open 'C:\\Users\\***\\AppData\\Local\\Temp\\Azurite\\__queuestorage__\\c297fef4-6975-48e5-8ec0-d52a8d302e1b'"
2022-09-20T00:39:28.490Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d error: ErrorMiddleware: Set HTTP code: 500
2022-09-20T00:39:28.490Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d info: EndMiddleware: End response. TotalTimeInMS=3 StatusCode=500 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.16.0"}
2022-09-20T00:39:28.490Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:0
2022-09-20T00:39:28.490Z c99b9019-7f75-4a1c-b0d1-1abaa94f166d debug: OperationQueue:execute() return. Operation.length === 0
Here is the next time I tried to write to the Queue after restarting my PC
2022-09-20T01:47:33.914Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: QueueStorageContextMiddleware: RequestMethod=PUT RequestURL=http://127.0.0.1/devstoreaccount1/recording-import-jobs RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","x-ms-client-request-id":"2bf3bd83-fcf3-4a63-abe3-0072e9ec9c33","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.4.2 (.NET 5.0.17; Microsoft Windows 10.0.19043)","x-ms-date":"Tue, 20 Sep 2022 01:47:33 GMT","authorization":"SharedKey devstoreaccount1:c5mt7FCfgnacjFBRIZx213kQi4e6gNeh4dI1Lg4YA0A=","traceparent":"00-3dd6a14e19d9ac4fadbc3a93122e7258-312fca6a80da0f4b-00","content-length":"0"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-20T01:47:33.914Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=undefined MessageId=undefined
2022-09-20T01:47:33.914Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 verbose: DispatchMiddleware: Dispatching request...
2022-09-20T01:47:33.915Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: DispatchMiddleware: Operation=Queue_Create
2022-09-20T01:47:33.915Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T01:47:33.915Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T01:47:33.915Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"PUT\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:2bf3bd83-fcf3-4a63-abe3-0072e9ec9c33\nx-ms-date:Tue, 20 Sep 2022 01:47:33 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs"
2022-09-20T01:47:33.915Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:c5mt7FCfgnacjFBRIZx213kQi4e6gNeh4dI1Lg4YA0A=
2022-09-20T01:47:33.915Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T01:47:33.915Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T01:47:33.915Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: HandlerMiddleware: DeserializedParameters={"options":{"metadata":{},"requestId":"2bf3bd83-fcf3-4a63-abe3-0072e9ec9c33"},"version":"2018-11-09"}
2022-09-20T01:47:33.916Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 verbose: SerializerMiddleware: Start serializing...
2022-09-20T01:47:33.916Z 0c74ece5-cd7f-4972-8220-4dc8657ec1e8 info: EndMiddleware: End response. TotalTimeInMS=2 StatusCode=204 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.16.0","x-ms-client-request-id":"2bf3bd83-fcf3-4a63-abe3-0072e9ec9c33","x-ms-request-id":"0c74ece5-cd7f-4972-8220-4dc8657ec1e8","x-ms-version":"2021-04-10","date":"Tue, 20 Sep 2022 01:47:33 GMT"}
2022-09-20T01:47:33.929Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: QueueStorageContextMiddleware: RequestMethod=GET RequestURL=http://127.0.0.1/devstoreaccount1/recording-import-jobs?comp=metadata RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","x-ms-client-request-id":"08add6c3-69d2-4365-a2a7-f9ff2d565ea5","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.4.2 (.NET 5.0.17; Microsoft Windows 10.0.19043)","x-ms-date":"Tue, 20 Sep 2022 01:47:33 GMT","authorization":"SharedKey devstoreaccount1:u053lkEbTyGJTTXuKEwWpaUxe8G1uC8tITxlWVBiycw=","traceparent":"00-3dd6a14e19d9ac4fadbc3a93122e7258-312fca6a80da0f4b-00"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-20T01:47:33.930Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=undefined MessageId=undefined
2022-09-20T01:47:33.930Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 verbose: DispatchMiddleware: Dispatching request...
2022-09-20T01:47:33.930Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: DispatchMiddleware: Operation=Queue_GetProperties
2022-09-20T01:47:33.930Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T01:47:33.930Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T01:47:33.930Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"GET\n\n\n\n\n\n\n\n\n\n\n\nx-ms-client-request-id:08add6c3-69d2-4365-a2a7-f9ff2d565ea5\nx-ms-date:Tue, 20 Sep 2022 01:47:33 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs\ncomp:metadata"
2022-09-20T01:47:33.930Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:u053lkEbTyGJTTXuKEwWpaUxe8G1uC8tITxlWVBiycw=
2022-09-20T01:47:33.930Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T01:47:33.931Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T01:47:33.931Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: HandlerMiddleware: DeserializedParameters={"options":{"requestId":"08add6c3-69d2-4365-a2a7-f9ff2d565ea5"},"comp":"metadata","version":"2018-11-09"}
2022-09-20T01:47:33.931Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 verbose: SerializerMiddleware: Start serializing...
2022-09-20T01:47:33.931Z e21474e5-ac20-4a23-a267-4e2bc0b967f0 info: EndMiddleware: End response. TotalTimeInMS=2 StatusCode=200 StatusMessage=undefined Headers={"server":"Azurite-Queue/3.16.0","x-ms-client-request-id":"08add6c3-69d2-4365-a2a7-f9ff2d565ea5","x-ms-approximate-messages-count":"0","x-ms-request-id":"e21474e5-ac20-4a23-a267-4e2bc0b967f0","x-ms-version":"2021-04-10","date":"Tue, 20 Sep 2022 01:47:33 GMT"}
2022-09-20T01:47:33.944Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: QueueStorageContextMiddleware: RequestMethod=POST RequestURL=http://127.0.0.1/devstoreaccount1/recording-import-jobs/messages RequestHeaders:{"host":"127.0.0.1:10001","x-ms-version":"2018-11-09","x-ms-client-request-id":"10506d26-e301-405a-988c-2dbd30198c4e","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Storage.Queues/12.4.2 (.NET 5.0.17; Microsoft Windows 10.0.19043)","x-ms-date":"Tue, 20 Sep 2022 01:47:33 GMT","authorization":"SharedKey devstoreaccount1:cva7XpG3p+LK/vdd0ojImbxbAhPoq2Bpg2CEi7vV990=","traceparent":"00-3dd6a14e19d9ac4fadbc3a93122e7258-312fca6a80da0f4b-00","content-type":"application/xml","content-length":"88"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2022-09-20T01:47:33.944Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: QueueStorageContextMiddleware: Account=devstoreaccount1 Queue=recording-import-jobs Message=messages MessageId=undefined
2022-09-20T01:47:33.944Z 294a7a59-2c28-4c56-a65c-6d5a7124963c verbose: DispatchMiddleware: Dispatching request...
2022-09-20T01:47:33.944Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: DispatchMiddleware: Operation=Messages_Enqueue
2022-09-20T01:47:33.945Z 294a7a59-2c28-4c56-a65c-6d5a7124963c verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2022-09-20T01:47:33.945Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: QueueSharedKeyAuthenticator:validate() Start validation against account shared key authentication.
2022-09-20T01:47:33.945Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: QueueSharedKeyAuthenticator:validate() [STRING TO SIGN]:"POST\n\n\n88\n\napplication/xml\n\n\n\n\n\n\nx-ms-client-request-id:10506d26-e301-405a-988c-2dbd30198c4e\nx-ms-date:Tue, 20 Sep 2022 01:47:33 GMT\nx-ms-return-client-request-id:true\nx-ms-version:2018-11-09\n/devstoreaccount1/devstoreaccount1/recording-import-jobs/messages"
2022-09-20T01:47:33.945Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: QueueSharedKeyAuthenticator:validate() Calculated authentication header based on key1: devstoreaccount1:cva7XpG3p+LK/vdd0ojImbxbAhPoq2Bpg2CEi7vV990=
2022-09-20T01:47:33.945Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: QueueSharedKeyAuthenticator:validate() Signature 1 matched.
2022-09-20T01:47:33.945Z 294a7a59-2c28-4c56-a65c-6d5a7124963c verbose: DeserializerMiddleware: Start deserializing...
2022-09-20T01:47:33.946Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: deserialize(): Raw request body string is (removed all empty characters) <QueueMessage><MessageText>X0p1ZmpSOWZpMHV4MGJPS1pkckIxQQ==</MessageText></QueueMessage>
2022-09-20T01:47:33.948Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: HandlerMiddleware: DeserializedParameters={"options":{"requestId":"10506d26-e301-405a-988c-2dbd30198c4e"},"version":"2018-11-09","queueMessage":{"messageText":"X0p1ZmpSOWZpMHV4MGJPS1pkckIxQQ=="},"body":"ReadableStream"}
2022-09-20T01:47:33.948Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: OperationQueue.operate() Schedule incoming job 0c78fb44-48da-4173-9fe9-a8ac9b012c06
2022-09-20T01:47:33.948Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:1
2022-09-20T01:47:33.948Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: FSExtentStore:appendExtent() Select extent from idle location for extent append operation. LocationId:0 extentId:213fbbeb-0ed5-45b6-a051-37835cdad95e offset:0 MAX_EXTENT_SIZE:67108864
2022-09-20T01:47:33.948Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:appendExtent() Get fd:undefined for extent:213fbbeb-0ed5-45b6-a051-37835cdad95e from cache.
2022-09-20T01:47:33.949Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:appendExtent() Open file:C:\Users\***\AppData\Local\Temp\Azurite\__queuestorage__\213fbbeb-0ed5-45b6-a051-37835cdad95e for extent:213fbbeb-0ed5-45b6-a051-37835cdad95e, get new fd:5
2022-09-20T01:47:33.949Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:appendExtent() Created write stream for fd:5
2022-09-20T01:47:33.949Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:appendExtent() Start writing to extent 213fbbeb-0ed5-45b6-a051-37835cdad95e
2022-09-20T01:47:33.949Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:streamPipe() Start piping data to write stream
2022-09-20T01:47:33.949Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:streamPipe() Readable stream triggers close event, 32 bytes piped
2022-09-20T01:47:33.949Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:streamPipe() Invoke write stream end()
2022-09-20T01:47:33.950Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:streamPipe() Readable stream triggers close event, 32 bytes piped
2022-09-20T01:47:33.950Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:streamPipe() Writable stream triggers finish event, after 32 bytes piped. Flush data to fd:5.
2022-09-20T01:47:33.952Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:streamPipe() Flush data to fd:5 successfully. Resolve streamPipe().
2022-09-20T01:47:33.952Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:appendExtent() Write finish, start updating extent metadata. extent:{"id":"213fbbeb-0ed5-45b6-a051-37835cdad95e","locationId":"Default","path":"213fbbeb-0ed5-45b6-a051-37835cdad95e","size":32,"lastModifiedInMS":1663638453952}
2022-09-20T01:47:33.952Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: FSExtentStore:appendExtent() Update extent metadata done. Resolve()
2022-09-20T01:47:33.952Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: OperationQueue.operate() Job 0c78fb44-48da-4173-9fe9-a8ac9b012c06 completes callback, resolve.
2022-09-20T01:47:33.952Z 294a7a59-2c28-4c56-a65c-6d5a7124963c verbose: SerializerMiddleware: Start serializing...
2022-09-20T01:47:33.953Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: Serializer: Raw response body string is <?xml version="1.0" encoding="UTF-8" standalone="yes"?><QueueMessagesList><QueueMessage><MessageId>39a9c61a-2434-423d-b4bd-a48233d92cfc</MessageId><InsertionTime>Tue, 20 Sep 2022 01:47:33 GMT</InsertionTime><ExpirationTime>Tue, 27 Sep 2022 01:47:33 GMT</ExpirationTime><PopReceipt>MjBTZXAyMDIyMDE6NDc6MzNhZjMw</PopReceipt><TimeNextVisible>Tue, 20 Sep 2022 01:47:33 GMT</TimeNextVisible></QueueMessage></QueueMessagesList>
2022-09-20T01:47:33.953Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: Serializer: Start returning stream body.
2022-09-20T01:47:33.953Z 294a7a59-2c28-4c56-a65c-6d5a7124963c info: EndMiddleware: End response. TotalTimeInMS=9 StatusCode=201 StatusMessage=Created Headers={"server":"Azurite-Queue/3.16.0","x-ms-client-request-id":"10506d26-e301-405a-988c-2dbd30198c4e","x-ms-request-id":"294a7a59-2c28-4c56-a65c-6d5a7124963c","x-ms-version":"2021-04-10","date":"Tue, 20 Sep 2022 01:47:33 GMT","content-type":"application/xml"}
2022-09-20T01:47:33.953Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: OperationQueue:execute() Current runningConcurrency:0 maxConcurrency:1 operations.length:0
2022-09-20T01:47:33.953Z 294a7a59-2c28-4c56-a65c-6d5a7124963c debug: OperationQueue:execute() return. Operation.length === 0
Here's the full log of this region from the last failure to the success after restarting the PC AzuriteQueueFail.txt
And here is the logs from the last successful queue write on the 19th, to the first failure on the morning of the 20th SuccessToFirstFailure.txt
@LukeBolly Checked both 2 logs provided. I can see Azurite tries to read/write to a local file, and the file cannot be opened for write. Before the failure to the beginning of the logs, there is no other operation from Azurite touching the file. It sounds like Azurite cannot write to a new local file under the workspace folder.
I mentioned earlier that the file was actually missing completely while the failures were happening, so the file somehow got deleted randomly.