CancellationToken Thread Safety

[devhl-labs]

I'm seeing an issue with timeouts occurring where they shouldn't. It seems like there may be another thread safety issue like this one. I'm seeing timeouts occur after only some seconds and it's reporting the command errored after 300 seconds. Here is the original issue I posted in npgsql repo.

#3579

Here is an example. It's reporting that it failed after 300 seconds, but notice the last line says 16. That 16 represents the number of seconds that passed between command received and command errored.

[ERR] 01:21 | Failed executing DbCommand ("301,729"ms)
[Parameters=["p0='13', p1='13', p2='#29PQLQQC9', p3='False',
p4='2021-02-07T00:00:00.0000000Z' (DbType = DateTime), p5=NULL
(Nullable = false) (DbType = Object), p6=NULL (Nullable = false)
(DbType = Object), p7=NULL (Nullable = false) (DbType = Object),
p8=NULL (Nullable = false) (DbType = Object), p9=NULL (Nullable =
false) (DbType = Object), p10=NULL (Nullable = false) (DbType =
Object)"], CommandType='Text', CommandTimeout='300']"\r\n""SELECT
l.hit_rate, l.name, l.successes, l.tag, l.tries\r\nFROM (\r\n
 select * from villageleader(@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7,
@p8, @p9, @p10)\r\n) AS l\r\nWHERE l.successes > 0"
[ERR] 01:21 | An exception occurred while iterating over the results
of a query for context type
'"MinionBot.db.MbDbContext"'."\r\n""System.InvalidOperationException:
An exception has been raised that is likely due to a transient
failure.\r\n ---> Npgsql.NpgsqlException (0x80004005): Exception while
reading from stream\r\n ---> System.TimeoutException: Timeout during
reading attempt\r\n   at
Npgsql.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|194_0(NpgsqlConnector
connector, Boolean async, DataRowLoadingMode dataRowLoadingMode,
Boolean readingNotifications, Boolean isReadingPrependedMessage)\r\n
at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean
isConsuming, CancellationToken cancellationToken)\r\n   at
Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean
async, CancellationToken cancellationToken)\r\n   at
Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean
async, CancellationToken cancellationToken)\r\n   at
Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior
behavior, CancellationToken cancellationToken)\r\n   at
Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject
parameterObject, CancellationToken cancellationToken)\r\n   at
Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject
parameterObject, CancellationToken cancellationToken)\r\n   at
Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(DbContext
_, Boolean result, CancellationToken cancellationToken)\r\n   at
Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState
state, Func`4 operation, Func`4 verifySucceeded, CancellationToken
cancellationToken)\r\n   --- End of inner exception stack trace
---\r\n   at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState
state, Func`4 operation, Func`4 verifySucceeded, CancellationToken
cancellationToken)\r\n   at
Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()"
System.InvalidOperationException: An exception has been raised that is
likely due to a transient failure.
 ---> Npgsql.NpgsqlException (0x80004005): Exception while reading from stream
 ---> System.TimeoutException: Timeout during reading attempt
   at Npgsql.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|194_0(NpgsqlConnector
connector, Boolean async, DataRowLoadingMode dataRowLoadingMode,
Boolean readingNotifications, Boolean isReadingPrependedMessage)
   at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean
isConsuming, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior,
Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior,
Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior
behavior, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject
parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject
parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(DbContext
_, Boolean result, CancellationToken cancellationToken)
   at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState
state, Func`4 operation, Func`4 verifySucceeded, CancellationToken
cancellationToken)
   --- End of inner exception stack trace ---
   at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState
state, Func`4 operation, Func`4 verifySucceeded, CancellationToken
cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
[warn] 01:21 | CJorange        | 16 | #29PQLQQC9 | vl 13 13 1 | An
exception has been raised that is likely due to a transient failure. |
Exception while reading from stream

[vonzshik]

I do not understand, why do you think there is a problem with the CancellationToken? Whenever the query is cancelled through it, it throws a different exception. Also, that would be a problem on the npgsql side.

[devhl-labs]

Duplicate of #3579