Hangfire.Console icon indicating copy to clipboard operation
Hangfire.Console copied to clipboard

PerformContext.WriteLine still not threadsafe

Open ascott18 opened this issue 7 years ago • 7 comments

I get the following exception when calling PerformContext.WriteLine in a multi-threaded context. First, exception (1) is thrown once, followed by many throws of exception (2) for each other thread that makes a call to WriteLine after exception (1) is thrown. After exception (1) has been thrown, all subsequent calls to ThrowIfCancellationRequested throw exception (3)

This job in question has [DisableConcurrentExecution], and also checks Hangfire.Server.ServerJobCancellationToken.ThrowIfCancellationRequested() periodically.

Exception (1)

 System.Transactions.TransactionAbortedException
              HResult=0x80131501
              Message=The transaction has aborted.
              Source=System.Transactions
              StackTrace:
               at System.Transactions.TransactionStateAborted.EndCommit(InternalTransaction tx)
               at System.Transactions.CommittableTransaction.Commit()
               at System.Transactions.TransactionScope.InternalDispose()
               at System.Transactions.TransactionScope.Dispose()
               at Hangfire.SqlServer.SqlServerStorage.UseTransaction[T](DbConnection dedicatedConnection, Func`3 func, Nullable`1 isolationLevel)
               at Hangfire.SqlServer.SqlServerStorage.UseTransaction(DbConnection dedicatedConnection, Action`2 action)
               at Hangfire.SqlServer.SqlServerWriteOnlyTransaction.Commit()
               at Hangfire.Console.Storage.ConsoleStorage.AddLine(ConsoleId consoleId, ConsoleLine line)
               at Hangfire.Console.Server.ConsoleContext.AddLine(ConsoleLine line)
               at Hangfire.Console.ConsoleExtensions.WriteLine(PerformContext context, String value)

            Inner Exception 1:
            SqlException: The transaction operation cannot be performed because there are pending requests working on this transaction.

Exception (2)

System.InvalidOperationException
             HResult=0x80131509
             Message=The requested operation cannot be completed because the connection has been broken.
             Source=System.Data
             StackTrace:
              at System.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
              at System.Data.SqlClient.SqlDelegatedTransaction.Initialize()
              at System.Transactions.TransactionStatePSPEOperation.PSPEInitialize(InternalTransaction tx, IPromotableSinglePhaseNotification promotableSinglePhaseNotification, Guid promoterType)
              at System.Transactions.TransactionStateActive.EnlistPromotableSinglePhase(InternalTransaction tx, IPromotableSinglePhaseNotification promotableSinglePhaseNotification, Transaction atomicTransaction, Guid promoterType)
              at System.Transactions.Transaction.EnlistPromotableSinglePhase(IPromotableSinglePhaseNotification promotableSinglePhaseNotification, Guid promoterType)
              at System.Transactions.Transaction.EnlistPromotableSinglePhase(IPromotableSinglePhaseNotification promotableSinglePhaseNotification)
              at System.Data.SqlClient.SqlInternalConnection.EnlistNonNull(Transaction tx)
              at System.Data.SqlClient.SqlInternalConnection.Enlist(Transaction tx)
              at System.Data.SqlClient.SqlInternalConnection.EnlistTransaction(Transaction transaction)
              at System.Data.SqlClient.SqlConnection.EnlistTransaction(Transaction transaction)
              at Hangfire.SqlServer.SqlServerStorage.<>c__DisplayClass27_0`1.<UseTransaction>b__0(DbConnection connection)
              at Hangfire.SqlServer.SqlServerStorage.UseConnection[T](DbConnection dedicatedConnection, Func`2 func)
              at Hangfire.SqlServer.SqlServerStorage.UseTransaction[T](DbConnection dedicatedConnection, Func`3 func, Nullable`1 isolationLevel)
              at Hangfire.SqlServer.SqlServerStorage.UseTransaction(DbConnection dedicatedConnection, Action`2 action)
              at Hangfire.SqlServer.SqlServerWriteOnlyTransaction.Commit()
              at Hangfire.Console.Storage.ConsoleStorage.AddLine(ConsoleId consoleId, ConsoleLine line)
              at Hangfire.Console.Server.ConsoleContext.AddLine(ConsoleLine line)
              at Hangfire.Console.ConsoleExtensions.WriteLine(PerformContext context, String value)

Exception (3)

System.Data.SqlClient.SqlException (0x80131904): Distributed transaction completed. Either enlist this session in a new transaction or the NULL transaction.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at Dapper.SqlMapper.ExecuteReaderWithFlagsFallback(IDbCommand cmd, Boolean wasClosed, CommandBehavior behavior)
   at Dapper.SqlMapper.<QueryImpl>d__125`1.MoveNext()
   at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
   at Dapper.SqlMapper.Query[T](IDbConnection cnn, String sql, Object param, IDbTransaction transaction, Boolean buffered, Nullable`1 commandTimeout, Nullable`1 commandType)
   at Hangfire.SqlServer.SqlServerConnection.<>c__DisplayClass9_0.<GetStateData>b__0(DbConnection connection)
   at Hangfire.SqlServer.SqlServerStorage.UseConnection[T](DbConnection dedicatedConnection, Func`2 func)
   at Hangfire.SqlServer.SqlServerConnection.GetStateData(String jobId)
   at Hangfire.Server.ServerJobCancellationToken.IsJobAborted()
   at Hangfire.Server.ServerJobCancellationToken.ThrowIfCancellationRequested()
   at <PRIVATE>
   at System.Threading.Tasks.Parallel.<>c__DisplayClass17_0`1.<ForWorker>b__1()
   at System.Threading.Tasks.Task.InnerInvokeWithArg(Task childTask)
   at System.Threading.Tasks.Task.<>c__DisplayClass176_0.<ExecuteSelfReplicating>b__0(Object )
ClientConnectionId:b35b47e6-c77e-48e7-80c5-47f8a92eb047
Error Number:8525,State:1,Class:16

ascott18 avatar Jan 10 '18 16:01 ascott18

(Title is in reference to https://github.com/pieceofsummer/Hangfire.Console/issues/43)

ascott18 avatar Jan 10 '18 16:01 ascott18

I think this is related to #45. Try using MutexAttribute instead of DisableConcurrentExecutionAttribute.

pieceofsummer avatar Jan 10 '18 17:01 pieceofsummer

I will add that this seems to be something that has happened recently. Previous versions of our application used the following versions for a long time running thousands of jobs without error:

<PackageReference Include="Hangfire.Console" Version="1.3.1" />
    <PackageReference Include="Hangfire.Core" Version="1.6.12" />
    <PackageReference Include="Hangfire.SqlServer" Version="1.6.12" />
    <PackageReference Include="Hangfire.AspNetCore" Version="1.6.12" />

We then upgraded to these versions, which is when all problems started:

<PackageReference Include="Hangfire.Core" Version="1.6.17" />
    <PackageReference Include="Hangfire.Console" Version="1.3.9" />
    <PackageReference Include="Hangfire.SqlServer" Version="1.6.17" />
    <PackageReference Include="Hangfire.AspNetCore" Version="1.6.17" />

I have also tested this with <PackageReference Include="Hangfire.Console" Version="1.3.10" /> with the same results.

ascott18 avatar Jan 10 '18 17:01 ascott18

Does it work without [DisableConcurrentExecution]? Looks like there's a conflict with keep-alive queries (performed by a distributed lock held by DisableConcurrentExecutionAttribute) sometimes. There's currently no way to open a dedicated connection for Console :(

Console writes from different threads themselves shouldn't be a problem because they are performed inside a lock.

pieceofsummer avatar Jan 10 '18 17:01 pieceofsummer

For what it's worth, I also encountered this exact same problem. It was due to to [DisableConcurrentExecution]. I replaced that with [Mutex] and that does the job. However, [Mutex] is technically part of Hangfire.Pro (I lifted it from a gist you posted somewhere else), so I'm not terribly certain of the legality of that as a workaround.

mprigge avatar Jan 31 '18 03:01 mprigge

@mprigge it wasn’t posted by me but by @odinserj himself, I just provided a link to his public gist. He might want to clarify his point on this, but I don’t think there’d be any legal issues here. As far as I know, he’d planned to supersede DisableConcurrentExecutionAttribute with MutexAttribute in the future versions of Hangfire anyways.

pieceofsummer avatar Jan 31 '18 03:01 pieceofsummer

Ah! Sorry - Should have looked closer. Okay, good deal. I like [Mutex] better as it's quite a bit more flexible, anyhow. Oh, just in case someone else finds themselves in the same boat and is looking at this thread, this is the gist for MutexAttribute we're talking about.

BTW - Fantastic job with this extension. Makes some of our longer-running background processes much, much easier to follow.

mprigge avatar Jan 31 '18 04:01 mprigge