Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Table service batch does not roll back update actions (merge and delete are fine) #1228

Closed
joelverhagen opened this issue Dec 18, 2021 · 2 comments
Closed

Table service batch does not roll back update actions (merge and delete are fine) #1228

joelverhagen opened this issue Dec 18, 2021 · 2 comments

Comments

@joelverhagen
Copy link
Contributor

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

table

Which version of the Azurite was used?

Locally running version of #1157

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

Git clone

What's the Node.js version?

16.13.0

What problem was encountered?

When a batch transaction with an update action (e.g. update-replace not update-merge) fails, the update action is not rolled back. We are missing a bit of book keeping. I have a local patch that fixes the problem.

Steps to reproduce the issue?

using Azure.Data.Tables;

var tableClient = new TableServiceClient("UseDevelopmentStorage=true");
var table = tableClient.GetTableClient("table0");
table.Delete();
table.Create();
table.AddEntity(new TableEntity("PK", "RK1"));
var etag2 = table.AddEntity(new TableEntity("PK", "RK2")).Headers.ETag!.Value;
try
{
    table.SubmitTransaction(new[]
    {
        new TableTransactionAction(TableTransactionActionType.UpdateReplace, new TableEntity("PK", "RK2"), etag2), // good
        new TableTransactionAction(TableTransactionActionType.UpdateReplace, new TableEntity("PK", "RK1"), etag2), // bad
    });
}
catch (TableTransactionFailedException)
{
    Console.WriteLine("Failed as expected.");
}
var entity2 = table.GetEntity<TableEntity>("PK", "RK2");
if (entity2.Value.ETag != etag2)
{
    Console.WriteLine("ETag changed!");
    Console.WriteLine("Expected: " + etag2);
    Console.WriteLine("Actual:   " + entity2.Value.ETag);
}
2021-12-18T23:24:16.135Z 	 info: Azurite Blob service is starting on 127.0.0.1:10000
2021-12-18T23:24:16.137Z 	 info: AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2021-12-18T23:24:16.137Z 	 info: AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2021-12-18T23:24:16.169Z 	 info: BlobGCManager:start() Starting BlobGCManager. Set status to Initializing.
2021-12-18T23:24:16.170Z 	 info: BlobGCManager:start() Trigger mark and sweep loop. Set status to Running.
2021-12-18T23:24:16.170Z 	 info: BlobGCManager:markSweepLoop() Start next mark and sweep.
2021-12-18T23:24:16.171Z 	 info: BlobGCManager:markSweep() Get all extents.
2021-12-18T23:24:16.172Z 	 info: BlobGCManager:start() BlobGCManager successfully started.
2021-12-18T23:24:16.184Z 	 info: BlobGCManager:markSweep() Got 0 extents.
2021-12-18T23:24:16.184Z 	 info: BlobGCManager:markSweep() Get referred extents.
2021-12-18T23:24:16.185Z 	 info: BlobGCManager:markSweep() Got referred extents, unreferenced extents count is 0.
2021-12-18T23:24:16.186Z 	 info: BlobGCManager:markSweepLoop() Mark and sweep finished, taken 16ms.
2021-12-18T23:24:16.186Z 	 info: BlobGCManager:markSweepLoop() Sleep for 600000ms.
2021-12-18T23:24:16.189Z 	 info: Azurite Blob service successfully listens on http://127.0.0.1:10000
2021-12-18T23:24:16.190Z 	 info: Azurite Queue service is starting on 127.0.0.1:10001
2021-12-18T23:24:16.190Z 	 info: AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2021-12-18T23:24:16.191Z 	 info: AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2021-12-18T23:24:16.216Z 	 info: QueueGCManager:start() Starting QueueGCManager, set status to Initializing
2021-12-18T23:24:16.216Z 	 info: QueueGCManager:start() Trigger mark and sweep loop, set status to Running.
2021-12-18T23:24:16.217Z 	 info: QueueGCManager:markSweepLoop() Start new mark and sweep.
2021-12-18T23:24:16.217Z 	 info: QueueGCManger:markSweep() Get all extents.
2021-12-18T23:24:16.217Z 	 info: QueueGCManager:start() QueueGCManager successfully started.
2021-12-18T23:24:16.218Z 	 info: QueueGCManager:marksweep() Get 0 extents.
2021-12-18T23:24:16.218Z 	 info: QueueGCManager:markSweep() Get referred extents, then remove from allExtents.
2021-12-18T23:24:16.218Z 	 info: QueueGCManager:markSweep() Got referred extents, unreferenced extents count is 0.
2021-12-18T23:24:16.218Z 	 info: QueueGCManager:markSweepLoop() Mark and sweep finished, take 1ms.
2021-12-18T23:24:16.218Z 	 info: QueueGCManager:markSweepLoop() Sleep for 60000
2021-12-18T23:24:16.220Z 	 info: Azurite Queue service successfully listens on http://127.0.0.1:10001
2021-12-18T23:24:16.221Z 	 info: Azurite Table service is starting on 127.0.0.1:10002
2021-12-18T23:24:16.221Z 	 info: AccountDataStore:init() Refresh accounts from environment variable AZURITE_ACCOUNTS with value undefined
2021-12-18T23:24:16.222Z 	 info: AccountDataStore:init() Fallback to default emulator account devstoreaccount1.
2021-12-18T23:24:16.232Z 	 info: Azurite Table service successfully listens on http://127.0.0.1:10002
2021-12-18T23:24:18.703Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: TableStorageContextMiddleware: RequestMethod=DELETE RequestURL=http://127.0.0.1/devstoreaccount1/Tables('table0') RequestHeaders:{"host":"127.0.0.1:10002","x-ms-version":"2019-02-02","accept":"application/json","x-ms-client-request-id":"ce4cf631-af90-4caf-b3b9-4dfea2139dc9","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Data.Tables/12.3.0 (.NET 6.0.0-rtm.21522.10; Microsoft Windows 10.0.22000)","x-ms-date":"Sat, 18 Dec 2021 23:24:18 GMT","authorization":"SharedKeyLite devstoreaccount1:dkoahCPRtOZcbXfxAnS70ovZBA8slVX7VJlSrQAIodo="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2021-12-18T23:24:18.703Z 91b2ea50-5cdb-4595-b842-14321dbc275d debug: tableStorageContextMiddleware: Dispatch pattern string: /Tables('table0')
2021-12-18T23:24:18.704Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: tableStorageContextMiddleware: Account=devstoreaccount1 tableName=table0
2021-12-18T23:24:18.704Z 91b2ea50-5cdb-4595-b842-14321dbc275d verbose: DispatchMiddleware: Dispatching request...
2021-12-18T23:24:18.706Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: DispatchMiddleware: Operation=Table_Delete
2021-12-18T23:24:18.706Z 91b2ea50-5cdb-4595-b842-14321dbc275d verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2021-12-18T23:24:18.707Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: TableSharedKeyLiteAuthenticator:validate() Start validation against account shared key authentication.
2021-12-18T23:24:18.707Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: TableSharedKeyLiteAuthenticator:validate() [STRING TO SIGN]:"Sat, 18 Dec 2021 23:24:18 GMT\n/devstoreaccount1/devstoreaccount1/Tables('table0')"
2021-12-18T23:24:18.708Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: TableSharedKeyLiteAuthenticator:validate() Calculated authentication header based on key1: SharedKeyLite devstoreaccount1:dkoahCPRtOZcbXfxAnS70ovZBA8slVX7VJlSrQAIodo=
2021-12-18T23:24:18.708Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: TableSharedKeyLiteAuthenticator:validate() Signature 1 matched.
2021-12-18T23:24:18.709Z 91b2ea50-5cdb-4595-b842-14321dbc275d verbose: DeserializerMiddleware: Start deserializing...
2021-12-18T23:24:18.711Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: HandlerMiddleware: DeserializedParameters={"version":"2019-02-02","options":{"requestId":"ce4cf631-af90-4caf-b3b9-4dfea2139dc9"}}
2021-12-18T23:24:18.714Z 91b2ea50-5cdb-4595-b842-14321dbc275d verbose: SerializerMiddleware: Start serializing...
2021-12-18T23:24:18.716Z 91b2ea50-5cdb-4595-b842-14321dbc275d info: EndMiddleware: End response. TotalTimeInMS=13 StatusCode=204 StatusMessage=undefined Headers={"server":"Azurite-Table/3.15.0","content-type":"application/json;odata=minimalmetadata","x-ms-client-request-id":"ce4cf631-af90-4caf-b3b9-4dfea2139dc9","x-ms-request-id":"91b2ea50-5cdb-4595-b842-14321dbc275d","x-ms-version":"2021-02-12","date":"Sat, 18 Dec 2021 23:24:18 GMT"}
2021-12-18T23:24:18.736Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 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":"2019-02-02","dataserviceversion":"3.0","accept":"application/json;odata=minimalmetadata","x-ms-client-request-id":"83d4267d-cdf1-456d-a862-cdfbb951b6d7","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Data.Tables/12.3.0 (.NET 6.0.0-rtm.21522.10; Microsoft Windows 10.0.22000)","x-ms-date":"Sat, 18 Dec 2021 23:24:18 GMT","authorization":"SharedKeyLite devstoreaccount1:C3RYda4Y24Kin5EUjHibVPaXmIMoWQ6cKzBHsrimd20=","content-type":"application/json;odata=nometadata","content-length":"22"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 debug: tableStorageContextMiddleware: Dispatch pattern string: /Tables
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: tableStorageContextMiddleware: Account=devstoreaccount1 tableName=undefined
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 verbose: DispatchMiddleware: Dispatching request...
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: DispatchMiddleware: Operation=Table_Create
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: TableSharedKeyLiteAuthenticator:validate() Start validation against account shared key authentication.
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: TableSharedKeyLiteAuthenticator:validate() [STRING TO SIGN]:"Sat, 18 Dec 2021 23:24:18 GMT\n/devstoreaccount1/devstoreaccount1/Tables"
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: TableSharedKeyLiteAuthenticator:validate() Calculated authentication header based on key1: SharedKeyLite devstoreaccount1:C3RYda4Y24Kin5EUjHibVPaXmIMoWQ6cKzBHsrimd20=
2021-12-18T23:24:18.737Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: TableSharedKeyLiteAuthenticator:validate() Signature 1 matched.
2021-12-18T23:24:18.738Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 verbose: DeserializerMiddleware: Start deserializing...
2021-12-18T23:24:18.739Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 debug: deserialize(): Raw request body string is (removed all empty characters) {"TableName":"table0"}
2021-12-18T23:24:18.740Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: HandlerMiddleware: DeserializedParameters={"options":{"queryOptions":{"format":"application/json;odata=minimalmetadata"},"requestId":"83d4267d-cdf1-456d-a862-cdfbb951b6d7","dataServiceVersion":"3.0"},"version":"2019-02-02","tableProperties":{"tableName":"table0"},"body":"ReadableStream"}
2021-12-18T23:24:18.743Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 verbose: SerializerMiddleware: Start serializing...
2021-12-18T23:24:18.744Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 debug: Serializer: Raw response body string is {"odata.metadata":"http://127.0.0.1:10002/devstoreaccount1/$metadata#Tables/@Element","TableName":"table0"}
2021-12-18T23:24:18.744Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: Serializer: Start returning stream body.
2021-12-18T23:24:18.744Z 091cdfab-3585-4cd2-9ee8-2f58cb231ac2 info: EndMiddleware: End response. TotalTimeInMS=8 StatusCode=201 StatusMessage=Created Headers={"server":"Azurite-Table/3.15.0","content-type":"application/json;odata=minimalmetadata","x-ms-client-request-id":"83d4267d-cdf1-456d-a862-cdfbb951b6d7","x-ms-request-id":"091cdfab-3585-4cd2-9ee8-2f58cb231ac2","x-ms-version":"2021-02-12","date":"Sat, 18 Dec 2021 23:24:18 GMT","preference-applied":"return-content"}
2021-12-18T23:24:18.777Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: TableStorageContextMiddleware: RequestMethod=POST RequestURL=http://127.0.0.1/devstoreaccount1/table0?$format=application%2Fjson%3Bodata%3Dminimalmetadata RequestHeaders:{"host":"127.0.0.1:10002","x-ms-version":"2019-02-02","dataserviceversion":"3.0","prefer":"return-no-content","accept":"application/json;odata=minimalmetadata","x-ms-client-request-id":"7d98e2dc-2134-4e2d-9ae6-7ade710ab321","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Data.Tables/12.3.0 (.NET 6.0.0-rtm.21522.10; Microsoft Windows 10.0.22000)","x-ms-date":"Sat, 18 Dec 2021 23:24:18 GMT","authorization":"SharedKeyLite devstoreaccount1:mKpyUqhoHaS+ybNIZ24WV0ciMEPA1+tUFyqiLDZCzgQ=","content-type":"application/json;odata=nometadata","content-length":"36"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2021-12-18T23:24:18.777Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b debug: tableStorageContextMiddleware: Dispatch pattern string: /table0
2021-12-18T23:24:18.777Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: tableStorageContextMiddleware: Account=devstoreaccount1 tableName=table0
2021-12-18T23:24:18.777Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b verbose: DispatchMiddleware: Dispatching request...
2021-12-18T23:24:18.778Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: DispatchMiddleware: Operation=Table_InsertEntity
2021-12-18T23:24:18.778Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2021-12-18T23:24:18.778Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: TableSharedKeyLiteAuthenticator:validate() Start validation against account shared key authentication.
2021-12-18T23:24:18.778Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: TableSharedKeyLiteAuthenticator:validate() [STRING TO SIGN]:"Sat, 18 Dec 2021 23:24:18 GMT\n/devstoreaccount1/devstoreaccount1/table0"
2021-12-18T23:24:18.778Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: TableSharedKeyLiteAuthenticator:validate() Calculated authentication header based on key1: SharedKeyLite devstoreaccount1:mKpyUqhoHaS+ybNIZ24WV0ciMEPA1+tUFyqiLDZCzgQ=
2021-12-18T23:24:18.778Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: TableSharedKeyLiteAuthenticator:validate() Signature 1 matched.
2021-12-18T23:24:18.779Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b verbose: DeserializerMiddleware: Start deserializing...
2021-12-18T23:24:18.779Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b debug: deserialize(): Raw request body string is (removed all empty characters) {"PartitionKey":"PK","RowKey":"RK1"}
2021-12-18T23:24:18.780Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: HandlerMiddleware: DeserializedParameters={"options":{"queryOptions":{"format":"application/json;odata=minimalmetadata"},"requestId":"7d98e2dc-2134-4e2d-9ae6-7ade710ab321","dataServiceVersion":"3.0","responsePreference":"return-no-content","tableEntityProperties":{"PartitionKey":"PK","RowKey":"RK1"}},"version":"2019-02-02","body":"ReadableStream"}
2021-12-18T23:24:18.782Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b verbose: SerializerMiddleware: Start serializing...
2021-12-18T23:24:18.782Z 8edbd658-efb4-44ae-aa5f-1e6e28a9e51b info: EndMiddleware: End response. TotalTimeInMS=5 StatusCode=204 StatusMessage=undefined Headers={"server":"Azurite-Table/3.15.0","content-type":"application/json;odata=minimalmetadata","x-ms-client-request-id":"7d98e2dc-2134-4e2d-9ae6-7ade710ab321","x-ms-request-id":"8edbd658-efb4-44ae-aa5f-1e6e28a9e51b","x-ms-version":"2021-02-12","date":"Sat, 18 Dec 2021 23:24:18 GMT","etag":"W/\"datetime'2021-12-18T23%3A24%3A18.7770000Z'\"","preference-applied":"return-no-content"}
2021-12-18T23:24:18.785Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: TableStorageContextMiddleware: RequestMethod=POST RequestURL=http://127.0.0.1/devstoreaccount1/table0?$format=application%2Fjson%3Bodata%3Dminimalmetadata RequestHeaders:{"host":"127.0.0.1:10002","x-ms-version":"2019-02-02","dataserviceversion":"3.0","prefer":"return-no-content","accept":"application/json;odata=minimalmetadata","x-ms-client-request-id":"b1518b74-1271-457f-a907-802f21a8e7ff","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Data.Tables/12.3.0 (.NET 6.0.0-rtm.21522.10; Microsoft Windows 10.0.22000)","x-ms-date":"Sat, 18 Dec 2021 23:24:18 GMT","authorization":"SharedKeyLite devstoreaccount1:mKpyUqhoHaS+ybNIZ24WV0ciMEPA1+tUFyqiLDZCzgQ=","content-type":"application/json;odata=nometadata","content-length":"36"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2021-12-18T23:24:18.785Z 695e7c2f-74d4-4751-abed-587a35917ae4 debug: tableStorageContextMiddleware: Dispatch pattern string: /table0
2021-12-18T23:24:18.785Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: tableStorageContextMiddleware: Account=devstoreaccount1 tableName=table0
2021-12-18T23:24:18.785Z 695e7c2f-74d4-4751-abed-587a35917ae4 verbose: DispatchMiddleware: Dispatching request...
2021-12-18T23:24:18.786Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: DispatchMiddleware: Operation=Table_InsertEntity
2021-12-18T23:24:18.786Z 695e7c2f-74d4-4751-abed-587a35917ae4 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2021-12-18T23:24:18.786Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: TableSharedKeyLiteAuthenticator:validate() Start validation against account shared key authentication.
2021-12-18T23:24:18.786Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: TableSharedKeyLiteAuthenticator:validate() [STRING TO SIGN]:"Sat, 18 Dec 2021 23:24:18 GMT\n/devstoreaccount1/devstoreaccount1/table0"
2021-12-18T23:24:18.787Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: TableSharedKeyLiteAuthenticator:validate() Calculated authentication header based on key1: SharedKeyLite devstoreaccount1:mKpyUqhoHaS+ybNIZ24WV0ciMEPA1+tUFyqiLDZCzgQ=
2021-12-18T23:24:18.787Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: TableSharedKeyLiteAuthenticator:validate() Signature 1 matched.
2021-12-18T23:24:18.787Z 695e7c2f-74d4-4751-abed-587a35917ae4 verbose: DeserializerMiddleware: Start deserializing...
2021-12-18T23:24:18.787Z 695e7c2f-74d4-4751-abed-587a35917ae4 debug: deserialize(): Raw request body string is (removed all empty characters) {"PartitionKey":"PK","RowKey":"RK2"}
2021-12-18T23:24:18.788Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: HandlerMiddleware: DeserializedParameters={"options":{"queryOptions":{"format":"application/json;odata=minimalmetadata"},"requestId":"b1518b74-1271-457f-a907-802f21a8e7ff","dataServiceVersion":"3.0","responsePreference":"return-no-content","tableEntityProperties":{"PartitionKey":"PK","RowKey":"RK2"}},"version":"2019-02-02","body":"ReadableStream"}
2021-12-18T23:24:18.788Z 695e7c2f-74d4-4751-abed-587a35917ae4 verbose: SerializerMiddleware: Start serializing...
2021-12-18T23:24:18.788Z 695e7c2f-74d4-4751-abed-587a35917ae4 info: EndMiddleware: End response. TotalTimeInMS=3 StatusCode=204 StatusMessage=undefined Headers={"server":"Azurite-Table/3.15.0","content-type":"application/json;odata=minimalmetadata","x-ms-client-request-id":"b1518b74-1271-457f-a907-802f21a8e7ff","x-ms-request-id":"695e7c2f-74d4-4751-abed-587a35917ae4","x-ms-version":"2021-02-12","date":"Sat, 18 Dec 2021 23:24:18 GMT","etag":"W/\"datetime'2021-12-18T23%3A24%3A18.7850000Z'\"","preference-applied":"return-no-content"}
2021-12-18T23:24:18.810Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: TableStorageContextMiddleware: RequestMethod=POST RequestURL=http://127.0.0.1/devstoreaccount1/$batch RequestHeaders:{"host":"127.0.0.1:10002","x-ms-version":"2019-02-02","dataserviceversion":"3.0","accept":"application/json","x-ms-client-request-id":"a5cf2e29-1528-444a-aa48-24e8ceb14d07","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Data.Tables/12.3.0 (.NET 6.0.0-rtm.21522.10; Microsoft Windows 10.0.22000)","x-ms-date":"Sat, 18 Dec 2021 23:24:18 GMT","authorization":"SharedKeyLite devstoreaccount1:zRyYgLJGL0Fs6YFIlCBUmb5f1xnpfN1aNWx3e9V25RI=","content-type":"multipart/mixed; boundary=batch_a2389361-d5c3-4afe-b29c-21d386169685","content-length":"1216"} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2021-12-18T23:24:18.811Z d3a6ecbe-37ad-4edc-977c-0c884be8decf debug: tableStorageContextMiddleware: Dispatch pattern string: /$batch
2021-12-18T23:24:18.811Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: tableStorageContextMiddleware: Account=devstoreaccount1 tableName=$batch
2021-12-18T23:24:18.811Z d3a6ecbe-37ad-4edc-977c-0c884be8decf verbose: DispatchMiddleware: Dispatching request...
2021-12-18T23:24:18.812Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: DispatchMiddleware: Operation=Table_Batch
2021-12-18T23:24:18.812Z d3a6ecbe-37ad-4edc-977c-0c884be8decf verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2021-12-18T23:24:18.812Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: TableSharedKeyLiteAuthenticator:validate() Start validation against account shared key authentication.
2021-12-18T23:24:18.812Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: TableSharedKeyLiteAuthenticator:validate() [STRING TO SIGN]:"Sat, 18 Dec 2021 23:24:18 GMT\n/devstoreaccount1/devstoreaccount1/$batch"
2021-12-18T23:24:18.812Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: TableSharedKeyLiteAuthenticator:validate() Calculated authentication header based on key1: SharedKeyLite devstoreaccount1:zRyYgLJGL0Fs6YFIlCBUmb5f1xnpfN1aNWx3e9V25RI=
2021-12-18T23:24:18.812Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: TableSharedKeyLiteAuthenticator:validate() Signature 1 matched.
2021-12-18T23:24:18.813Z d3a6ecbe-37ad-4edc-977c-0c884be8decf verbose: DeserializerMiddleware: Start deserializing...
2021-12-18T23:24:18.813Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: HandlerMiddleware: DeserializedParameters={"version":"2019-02-02","options":{"requestId":"a5cf2e29-1528-444a-aa48-24e8ceb14d07","dataServiceVersion":"3.0"},"multipartContentType":"multipart/mixed; boundary=batch_a2389361-d5c3-4afe-b29c-21d386169685","contentLength":1216,"body":"ReadableStream"}
2021-12-18T23:24:18.815Z d3a6ecbe-37ad-4edc-977c-0c884be8decf debug: TableHandler:batch() Raw request string is "--batch_a2389361-d5c3-4afe-b29c-21d386169685\r\nContent-Type: multipart/mixed; boundary=changeset_7066d286-4693-41f7-97d9-01a6bb07ce88\r\n\r\n--changeset_7066d286-4693-41f7-97d9-01a6bb07ce88\r\nContent-Type: application/http\r\nContent-Transfer-Encoding: binary\r\n\r\nPUT http://127.0.0.1:10002/devstoreaccount1/table0(PartitionKey='PK',RowKey='RK2')?$format=application%2Fjson%3Bodata%3Dminimalmetadata HTTP/1.1\r\nHost: 127.0.0.1\r\nx-ms-version: 2019-02-02\r\nDataServiceVersion: 3.0\r\nIf-Match: W/\"datetime'2021-12-18T23%3A24%3A18.7850000Z'\"\r\nAccept: application/json\r\nContent-Type: application/json\r\n\r\n{\"PartitionKey\":\"PK\",\"RowKey\":\"RK2\"}\r\n--changeset_7066d286-4693-41f7-97d9-01a6bb07ce88\r\nContent-Type: application/http\r\nContent-Transfer-Encoding: binary\r\n\r\nPUT http://127.0.0.1:10002/devstoreaccount1/table0(PartitionKey='PK',RowKey='RK1')?$format=application%2Fjson%3Bodata%3Dminimalmetadata HTTP/1.1\r\nHost: 127.0.0.1\r\nx-ms-version: 2019-02-02\r\nDataServiceVersion: 3.0\r\nIf-Match: W/\"datetime'2021-12-18T23%3A24%3A18.7850000Z'\"\r\nAccept: application/json\r\nContent-Type: application/json\r\n\r\n{\"PartitionKey\":\"PK\",\"RowKey\":\"RK1\"}\r\n--changeset_7066d286-4693-41f7-97d9-01a6bb07ce88--\r\n\r\n--batch_a2389361-d5c3-4afe-b29c-21d386169685--\r\n"
2021-12-18T23:24:18.821Z d3a6ecbe-37ad-4edc-977c-0c884be8decf debug: TableHandler:batch() Raw response string is "--batchresponse_a2389361-d5c3-4afe-b29c-21d386169685\r\nContent-Type: multipart/mixed; boundary=changesetresponse_7066d286-4693-41f7-97d9-01a6bb07ce88\r\n\r\n--changesetresponse_7066d286-4693-41f7-97d9-01a6bb07ce88\r\nContent-Type: application/http\r\nContent-Transfer-Encoding: binary\r\n\r\nHTTP/1.1 412 STATUS_CODE_NOT_IMPLEMENTED\r\nContent-ID: 2\r\nDataServiceVersion: 3.0;\r\nContent-Type: application/json;odata=minimalmetadata;charset=utf-8\r\n\r\n{\"odata.error\":{\"code\":\"UpdateConditionNotSatisfied\",\"message\":{\"lang\":\"en-US\",\"value\":\"The update condition specified in the request was not satisfied.\\nRequestId:d3a6ecbe-37ad-4edc-977c-0c884be8decf\\nTime:2021-12-18T23:24:18.820Z\"}}}\r\n--changesetresponse_7066d286-4693-41f7-97d9-01a6bb07ce88--\r\n--batchresponse_a2389361-d5c3-4afe-b29c-21d386169685--\r\n"
2021-12-18T23:24:18.821Z d3a6ecbe-37ad-4edc-977c-0c884be8decf verbose: SerializerMiddleware: Start serializing...
2021-12-18T23:24:18.822Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: Serializer: Start returning stream body.
2021-12-18T23:24:18.824Z d3a6ecbe-37ad-4edc-977c-0c884be8decf info: EndMiddleware: End response. TotalTimeInMS=14 StatusCode=202 StatusMessage=Accepted Headers={"server":"Azurite-Table/3.15.0","content-type":"multipart/mixed; boundary=batchresponse_a2389361-d5c3-4afe-b29c-21d386169685","x-ms-request-id":"d3a6ecbe-37ad-4edc-977c-0c884be8decf","x-ms-version":"2021-02-12","date":"Sat, 18 Dec 2021 23:24:18 GMT"}
2021-12-18T23:24:18.886Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: TableStorageContextMiddleware: RequestMethod=GET RequestURL=http://127.0.0.1/devstoreaccount1/table0(PartitionKey='PK',RowKey='RK2')?$format=application%2Fjson%3Bodata%3Dminimalmetadata RequestHeaders:{"host":"127.0.0.1:10002","x-ms-version":"2019-02-02","dataserviceversion":"3.0","accept":"application/json;odata=minimalmetadata","x-ms-client-request-id":"1d4fcf93-543d-4474-9669-9b55709ed68b","x-ms-return-client-request-id":"true","user-agent":"azsdk-net-Data.Tables/12.3.0 (.NET 6.0.0-rtm.21522.10; Microsoft Windows 10.0.22000)","x-ms-date":"Sat, 18 Dec 2021 23:24:18 GMT","authorization":"SharedKeyLite devstoreaccount1:oU2GEQd1repxFGUVb9XZgE8Eu07VdzgIqvavhkG5Whc="} ClientIP=127.0.0.1 Protocol=http HTTPVersion=1.1
2021-12-18T23:24:18.886Z 5ab28919-b017-407e-95bc-8c7505f5b384 debug: tableStorageContextMiddleware: Dispatch pattern string: /table0(PartitionKey='PLACEHOLDER',RowKey='PLACEHOLDER')
2021-12-18T23:24:18.886Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: tableStorageContextMiddleware: Account=devstoreaccount1 tableName=table0
2021-12-18T23:24:18.886Z 5ab28919-b017-407e-95bc-8c7505f5b384 verbose: DispatchMiddleware: Dispatching request...
2021-12-18T23:24:18.887Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: DispatchMiddleware: Operation=Table_QueryEntitiesWithPartitionAndRowKey
2021-12-18T23:24:18.887Z 5ab28919-b017-407e-95bc-8c7505f5b384 verbose: AuthenticationMiddlewareFactory:createAuthenticationMiddleware() Validating authentications.
2021-12-18T23:24:18.887Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: TableSharedKeyLiteAuthenticator:validate() Start validation against account shared key authentication.
2021-12-18T23:24:18.887Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: TableSharedKeyLiteAuthenticator:validate() [STRING TO SIGN]:"Sat, 18 Dec 2021 23:24:18 GMT\n/devstoreaccount1/devstoreaccount1/table0(PartitionKey='PK',RowKey='RK2')"
2021-12-18T23:24:18.887Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: TableSharedKeyLiteAuthenticator:validate() Calculated authentication header based on key1: SharedKeyLite devstoreaccount1:oU2GEQd1repxFGUVb9XZgE8Eu07VdzgIqvavhkG5Whc=
2021-12-18T23:24:18.887Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: TableSharedKeyLiteAuthenticator:validate() Signature 1 matched.
2021-12-18T23:24:18.887Z 5ab28919-b017-407e-95bc-8c7505f5b384 verbose: DeserializerMiddleware: Start deserializing...
2021-12-18T23:24:18.888Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: HandlerMiddleware: DeserializedParameters={"options":{"queryOptions":{"format":"application/json;odata=minimalmetadata"},"requestId":"1d4fcf93-543d-4474-9669-9b55709ed68b","dataServiceVersion":"3.0"},"version":"2019-02-02"}
2021-12-18T23:24:18.889Z 5ab28919-b017-407e-95bc-8c7505f5b384 debug: TableHandler:queryEntities() Raw response string is "{\"odata.metadata\":\"http://127.0.0.1:10002/devstoreaccount1/$metadata#table0/@Element\",\"odata.etag\":\"W/\\\"datetime'2021-12-18T23%3A24%3A18.8100000Z'\\\"\",\"PartitionKey\":\"PK\",\"RowKey\":\"RK2\",\"Timestamp@odata.type\":\"Edm.DateTime\",\"Timestamp\":\"2021-12-18T23:24:18.8100000Z\"}"
2021-12-18T23:24:18.889Z 5ab28919-b017-407e-95bc-8c7505f5b384 verbose: SerializerMiddleware: Start serializing...
2021-12-18T23:24:18.889Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: Serializer: Start returning stream body.
2021-12-18T23:24:18.891Z 5ab28919-b017-407e-95bc-8c7505f5b384 info: EndMiddleware: End response. TotalTimeInMS=5 StatusCode=200 StatusMessage=OK Headers={"server":"Azurite-Table/3.15.0","content-type":"application/json;odata=minimalmetadata","x-ms-client-request-id":"1d4fcf93-543d-4474-9669-9b55709ed68b","x-ms-request-id":"5ab28919-b017-407e-95bc-8c7505f5b384","x-ms-version":"2021-02-12","date":"Sat, 18 Dec 2021 23:24:18 GMT"}
2021-12-18T23:24:23.520Z 	 info: Azurite Blob service is closing...
2021-12-18T23:24:23.520Z 	 info: Azurite Queue service is closing...
2021-12-18T23:24:23.521Z 	 info: Azurite Table service is closing...
2021-12-18T23:24:23.523Z 	 info: BlobGCManager:close() Start closing BlobGCManager. Set status to Closing.
2021-12-18T23:24:23.523Z 	 info: QueueGCManager:close() Start closing QueueGCManager, set status to Closing.
2021-12-18T23:24:23.523Z 	 info: BlobGCManager:start() Mark and sweep loop is closed.
2021-12-18T23:24:23.524Z 	 info: BlobGCManager:close() BlobGCManager successfully closed. Set status to Closed.
2021-12-18T23:24:23.524Z 	 info: QueueGCManager:start() Mark and sweep loop is closed.
2021-12-18T23:24:23.524Z 	 info: QueueGCManager:close() QueueGCManager successfully closed, set status to Closed.
2021-12-18T23:24:23.524Z 	 info: Azurite Table service successfully closed
2021-12-18T23:24:23.525Z 	 info: Azurite Blob service successfully closed
2021-12-18T23:24:23.525Z 	 info: Azurite Queue service successfully closed

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?
@joelverhagen
Copy link
Contributor Author

The fix appears to be:

diff --git a/src/table/persistence/LokiTableMetadataStore.ts b/src/table/persistence/LokiTableMetadataStore.ts
index 1514628..b5d8543 100644
--- a/src/table/persistence/LokiTableMetadataStore.ts
+++ b/src/table/persistence/LokiTableMetadataStore.ts
@@ -676,6 +676,9 @@ export default class LokiTableMetadataStore implements ITableMetadataStore {
     if (!doc) {
       throw StorageErrorFactory.getEntityNotFound(context);
     }
+    if (batchID) {
+      this.transactionRollbackTheseEntities.push(doc);
+    }
 
     // Test if etag value is valid
     const encodedEtag = doc.eTag.replace(":", "%3A").replace(":", "%3A");

@joelverhagen joelverhagen mentioned this issue Dec 19, 2021
Closed
23 tasks
@edwin-huber
Copy link
Collaborator

Thanks for catching this.
Adding a test case and including the rollback on updateTableEntity()

edwin-huber added a commit to edwin-huber/Azurite that referenced this issue Jan 12, 2022
@edwin-huber
fixes Azure#1228 by adding the updateTableEntity to transaction rollback
6388cce
edwin-huber added a commit to edwin-huber/Azurite that referenced this issue Jan 12, 2022
@edwin-huber
updated batch rollback tests to check etags after update, as noted in A…
3082f69 
…zure#1228
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@joelverhagen @edwin-huber