enowars / EnoEngine

MIT License
12 stars 2 forks source link

EnoFlagSink crashes ("A command is already in progress") #125

Closed Trolldemorted closed 3 years ago

Trolldemorted commented 3 years ago
fail: EnoFlagSink.FlagSubmissionEndpoint[0]
      InsertSubmissionsLoop dropping batch because: InsertSubmissionsLoop failed: A command is already in progress: insert into "SubmittedFlags" ("FlagServiceId", "FlagRoundId", "FlagOwnerId", "FlagRoundOffset", "AttackerTeamId", "RoundId", "SubmissionsCount", "Timestamp")
      values (2, 247, 5, 0, 2, 251, 1, NOW()),(2, 244, 5, 0, 2, 251, 1, NOW()),(2, 238, 5, 0, 2, 251, 1, NOW())
      on conflict ("FlagServiceId", "FlagRoundId", "FlagOwnerId", "FlagRoundOffset", "AttackerTeamId") do update set "SubmissionsCount" = "SubmittedFlags"."SubmissionsCount" + excluded."SubmissionsCount" returning "FlagServiceId", "FlagOwnerId", "FlagRoundId", "FlagRoundOffset", "AttackerTeamId", "RoundId", "SubmissionsCount", "Timestamp";
       (Npgsql.NpgsqlOperationInProgressException)
         at Npgsql.NpgsqlConnector.<StartUserAction>g__DoStartUserAction|205_0(<>c__DisplayClass205_0& )
         at Npgsql.NpgsqlConnector.StartUserAction(ConnectorState newState, NpgsqlCommand command)
         at Npgsql.NpgsqlConnector.Rollback(Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlTransaction.Rollback()
         at Npgsql.NpgsqlTransaction.Dispose(Boolean disposing)
         at Microsoft.EntityFrameworkCore.Storage.RelationalTransaction.Dispose()
         at EnoDatabase.EnoDatabase.ProcessSubmissionsBatch(List`1 submissions, Int64 flagValidityInRounds, EnoStatistics statistics) in /services/EnoEngine/EnoDatabase/EnoDatabase.FlagSubmission.cs:line 134
         at EnoDatabase.EnoDatabaseUtil.RetryScopedDatabaseAction(IServiceProvider serviceProvider, Func`2 function) in /services/EnoEngine/EnoDatabase/EnoDatabaseUtil.cs:line 33
         at EnoFlagSink.FlagSubmissionEndpoint.InsertSubmissionsLoop(Int32 number, CancellationToken token) in /services/EnoEngine/EnoFlagSink/FlagSubmissionEndpoint.cs:line 403
crit: EnoFlagSink.FlagSubmissionEndpoint[0]
      InsertSubmissionsLoop failed: InsertSubmissionsLoop failed: An attempt was made to transition a task to a final state when it had already completed. (System.InvalidOperationException)
         at EnoFlagSink.FlagSubmissionEndpoint.InsertSubmissionsLoop(Int32 number, CancellationToken token) in /services/EnoEngine/EnoFlagSink/FlagSubmissionEndpoint.cs:line 412
Trolldemorted commented 3 years ago

Woops, the crash was caused by:

crit: EnoFlagSink.FlagSubmissionEndpoint[0]
      InsertSubmissionsLoop failed: InsertSubmissionsLoop failed: An attempt was made to transition a task to a final state when it had already completed. (System.InvalidOperationException)                                                                                  at EnoFlagSink.FlagSubmissionEndpoint.InsertSubmissionsLoop(Int32 number, CancellationToken token) in /services/EnoEngine/EnoFlagSink/FlagSubmissionEndpoint.cs:line 412
Trolldemorted commented 3 years ago

I assume the crit happened because inside the batch processing some flags' tcs were already completed (old/own), so the tcs was completed a second time afterwards

Trolldemorted commented 3 years ago

ftr, this was on 1244f450cb228d720df8ea2a14d18ad6018acc82

Trolldemorted commented 3 years ago

My best bet is this was due to https://github.com/npgsql/npgsql/issues/3306. They have released a stable 5.0 version now, let's hope this won't happen again. Meanwhile, I will ensure we log failed transactions more duefully.