Random The operation was canceled

Jiri · February 4, 2022, 8:10am

I’m submitting a…

[ ] Regression (a behavior that stopped working in a new release)
[x] Bug report
[ ] Performance issue
[ ] Documentation issue or request

Current behavior

I found that I have seemingly random errors in log. Mostly with The operation was canceled.

Few examples:

Getting assets (which should exist).

message: 'The operation was canceled.', stackTrace: '   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at MongoDB.Driver.Core.Misc.SemaphoreSlimSignalable.IsSignaled(CancellationTokenSource signalTokenSource, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Misc.SemaphoreSlimSignalable.WaitSignaledAsync(TimeSpan timeout, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool.ConnectionCreator.CreateOpenedOrReuseAsync(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool.AcquireConnectionHelper.AcquireConnectionAsync(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool.AcquireConnectionAsync(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.Server.GetChannelAsync(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.RetryableReadContext.InitializeAsync(CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.RetryableReadContext.CreateAsync(IReadBinding binding, Boolean retryRequested, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.FindOperation`1.ExecuteAsync(IReadBinding binding, CancellationToken cancellationToken)
   at MongoDB.Driver.OperationExecutor.ExecuteReadOperationAsync[TResult](IReadBinding binding, IReadOperation`1 operation, CancellationToken cancellationToken)
   at MongoDB.Driver.MongoCollectionImpl`1.ExecuteReadOperationAsync[TResult](IClientSessionHandle session, IReadOperation`1 operation, ReadPreference readPreference, CancellationToken cancellationToken)
   at MongoDB.Driver.MongoCollectionImpl`1.UsingImplicitSessionAsync[TResult](Func`2 funcAsync, CancellationToken cancellationToken)
   at MongoDB.Driver.IAsyncCursorSourceExtensions.FirstOrDefaultAsync[TDocument](IAsyncCursorSource`1 source, CancellationToken cancellationToken)
   at Squidex.Domain.Apps.Entities.MongoDb.Assets.MongoAssetRepository.FindAssetAsync(DomainId appId, DomainId id, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities.MongoDb/Assets/MongoAssetRepository.cs:line 217
   at Squidex.Domain.Apps.Entities.Assets.Queries.AssetQueryService.FindCoreAsync(Context context, DomainId id, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities/Assets/Queries/AssetQueryService.cs:line 313
   at Squidex.Domain.Apps.Entities.Assets.Queries.AssetQueryService.FindAsync(Context context, DomainId id, Int64 version, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities/Assets/Queries/AssetQueryService.cs:line 167
   at Squidex.Areas.Api.Controllers.Assets.AssetContentController.GetAssetContentBySlug(String app, String idOrSlug, AssetContentQueryDto request, String more) in /src/src/Squidex/Areas/Api/Controllers/Assets/AssetContentController.cs:line 77
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Logged|12_1(ControllerActionInvoker invoker)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextExceptionFilterAsync>g__Awaited|26_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)', type: 'System.OperationCanceledException'

Here is request with query assets i believe.

{message: 'The operation was canceled.', stackTrace: '   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveMessageAsync(Int32 responseTo, IMessageEncoderSelector encoderSelector, MessageEncoderSettings messageEncoderSettings, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool.PooledConnection.ReceiveMessageAsync(Int32 responseTo, IMessageEncoderSelector encoderSelector, MessageEncoderSettings messageEncoderSettings, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.WireProtocol.CommandUsingCommandMessageWireProtocol`1.ExecuteAsync(IConnection connection, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.Server.ServerChannel.ExecuteProtocolAsync[TResult](IWireProtocol`1 protocol, ICoreSession session, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.RetryableReadOperationExecutor.ExecuteAsync[TResult](IRetryableReadOperation`1 operation, RetryableReadContext context, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.ReadCommandOperation`1.ExecuteAsync(RetryableReadContext context, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.AggregateOperation`1.ExecuteAsync(RetryableReadContext context, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.AggregateOperation`1.ExecuteAsync(IReadBinding binding, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.CountDocumentsOperation.ExecuteAsync(IReadBinding binding, CancellationToken cancellationToken)
   at MongoDB.Driver.OperationExecutor.ExecuteReadOperationAsync[TResult](IReadBinding binding, IReadOperation`1 operation, CancellationToken cancellationToken)
   at MongoDB.Driver.MongoCollectionImpl`1.ExecuteReadOperationAsync[TResult](IClientSessionHandle session, IReadOperation`1 operation, ReadPreference readPreference, CancellationToken cancellationToken)
   at MongoDB.Driver.MongoCollectionImpl`1.UsingImplicitSessionAsync[TResult](Func`2 funcAsync, CancellationToken cancellationToken)
   at Squidex.Domain.Apps.Entities.MongoDb.Assets.MongoAssetRepository.QueryAsync(DomainId appId, Nullable`1 parentId, Q q, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities.MongoDb/Assets/MongoAssetRepository.cs:line 146
   at Squidex.Domain.Apps.Entities.Assets.Queries.AssetQueryService.QueryCoreAsync(Context context, Nullable`1 parentId, Q q, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities/Assets/Queries/AssetQueryService.cs:line 253
   at Squidex.Domain.Apps.Entities.Assets.Queries.AssetQueryService.QueryAsync(Context context, Nullable`1 parentId, Q q, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities/Assets/Queries/AssetQueryService.cs:line 192
   at Squidex.Areas.Api.Controllers.Assets.AssetsController.GetAssets(String app, Nullable`1 parentId, String ids, String q) in /src/src/Squidex/Areas/Api/Controllers/Assets/AssetsController.cs:line 130
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Logged|12_1(ControllerActionInvoker invoker)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextExceptionFilterAsync>g__Awaited|26_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)', type: 'System.OperationCanceledException'}

Here standart entity

{message: 'The operation was canceled.', stackTrace: '   at MongoDB.Driver.Core.Connections.BinaryConnection.ReceiveMessageAsync(Int32 responseTo, IMessageEncoderSelector encoderSelector, MessageEncoderSettings messageEncoderSettings, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool.PooledConnection.ReceiveMessageAsync(Int32 responseTo, IMessageEncoderSelector encoderSelector, MessageEncoderSettings messageEncoderSettings, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.WireProtocol.CommandUsingCommandMessageWireProtocol`1.ExecuteAsync(IConnection connection, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Servers.Server.ServerChannel.ExecuteProtocolAsync[TResult](IWireProtocol`1 protocol, ICoreSession session, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.RetryableReadOperationExecutor.ExecuteAsync[TResult](IRetryableReadOperation`1 operation, RetryableReadContext context, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.ReadCommandOperation`1.ExecuteAsync(RetryableReadContext context, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.FindCommandOperation`1.ExecuteAsync(RetryableReadContext context, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.FindOperation`1.ExecuteAsync(RetryableReadContext context, CancellationToken cancellationToken)
   at MongoDB.Driver.Core.Operations.FindOperation`1.ExecuteAsync(IReadBinding binding, CancellationToken cancellationToken)
   at MongoDB.Driver.OperationExecutor.ExecuteReadOperationAsync[TResult](IReadBinding binding, IReadOperation`1 operation, CancellationToken cancellationToken)
   at MongoDB.Driver.MongoCollectionImpl`1.ExecuteReadOperationAsync[TResult](IClientSessionHandle session, IReadOperation`1 operation, ReadPreference readPreference, CancellationToken cancellationToken)
   at MongoDB.Driver.MongoCollectionImpl`1.UsingImplicitSessionAsync[TResult](Func`2 funcAsync, CancellationToken cancellationToken)
   at MongoDB.Driver.IAsyncCursorSourceExtensions.FirstOrDefaultAsync[TDocument](IAsyncCursorSource`1 source, CancellationToken cancellationToken)
   at Squidex.Domain.Apps.Entities.MongoDb.Contents.Operations.QueryById.QueryAsync(ISchemaEntity schema, DomainId id, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities.MongoDb/Contents/Operations/QueryById.cs:line 37
   at Squidex.Domain.Apps.Entities.MongoDb.Contents.MongoContentCollection.FindContentAsync(ISchemaEntity schema, DomainId id, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities.MongoDb/Contents/MongoContentCollection.cs:line 176
   at Squidex.Domain.Apps.Entities.Contents.Queries.ContentQueryService.FindCoreAsync(Context context, DomainId id, ISchemaEntity schema, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities/Contents/Queries/ContentQueryService.cs:line 253
   at Squidex.Domain.Apps.Entities.Contents.Queries.ContentQueryService.FindAsync(Context context, String schemaIdOrName, DomainId id, Int64 version, CancellationToken ct) in /src/src/Squidex.Domain.Apps.Entities/Contents/Queries/ContentQueryService.cs:line 77
   at Squidex.Areas.Api.Controllers.Contents.ContentsController.GetContent(String app, String schema, DomainId id) in /src/src/Squidex/Areas/Api/Controllers/Contents/ContentsController.cs:line 212
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Logged|12_1(ControllerActionInvoker invoker)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextExceptionFilterAsync>g__Awaited|26_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)', type: 'System.OperationCanceledException'}

Expected behavior

No errors.

Environment

[x] Self hosted with docker
[ ] Self hosted with IIS
[ ] Self hosted with other version
[ ] Cloud version

Version: 6.5.0.0

Sebastian · February 4, 2022, 8:34am

Hi,

this exception is kind of normal. e.g. it can happen when a request is aborted by the client.

But there are also a few timeout to ensure that the system stays stable:

github.com

Squidex/squidex/blob/master/backend/src/Squidex/appsettings.json#L249


// The maximum file size in bytes. Default: 5MB
"maxSize": 5242880,

// True to delete assets recursively.
"deleteRecursive": true,

// True to delete assets files permanently.
"deletePermanent": false,

// The timeout when searching for single items in the database.
"timeoutFind": "00:00:01",

// The timeout when searching for multiple items in the database.
"timeoutQuery": "00:00:05",

// Create one folder per app.
//
// WARNING: If you change this parameter, previous assets are not available anymore.
"folderPerApp": false,

// Points to another Squidex instance, which should be configured as resizer.

You can try to increase them. If you use Mongo Atlas you can also check the average performance of your queries and whether they are higher than the timeouts.

MongoDB has also an integrated profiler, which can be useful: https://docs.mongodb.com/manual/reference/method/db.setProfilingLevel/

Jiri · February 4, 2022, 9:22am

Thanks for your reply. I try to increase those limits slightly for now I and if that does not help then I have to learn more about Mongo profiler.