[SOLVED] MongoDB error for graphql query

alexmatskevich · May 20, 2020, 10:21pm

I have…

[x ] Checked the logs and have uploaded a log file and provided a link because I found something suspicious there.

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

Hello. I have the next failed graphql query:

Full error trace:

“logLevel”: “Warning”,
“action”: “reolveField”,
“status”: “failed”,
“field”: “queryEstatesContents”,
“exception”: {
“type”: “MongoDB.Driver.MongoCommandException”,
“message”: “Command find failed: Executor error during find command: OperationFailed: Sort operation used more than the maximum 33554432 bytes of RAM. Add an index, or specify a smaller limit…”,
“stackTrace”: " at MongoDB.Driver.Core.WireProtocol.CommandUsingCommandMessageWireProtocol1.ProcessResponse(ConnectionId connectionId, CommandMessage responseMessage)\n at MongoDB.Driver.Core.WireProtocol.CommandUsingCommandMessageWireProtocol1.ExecuteAsync(IConnection connection, CancellationToken cancellationToken)\n at MongoDB.Driver.Core.Servers.Server.ServerChannel.ExecuteProtocolAsync[TResult](IWireProtocol1 protocol, CancellationToken cancellationToken)\n at MongoDB.Driver.Core.Operations.RetryableReadOperationExecutor.ExecuteAsync[TResult](IRetryableReadOperation1 operation, RetryableReadContext context, CancellationToken cancellationToken)\n at MongoDB.Driver.Core.Operations.ReadCommandOperation1.ExecuteAsync(RetryableReadContext context, CancellationToken cancellationToken)\n at MongoDB.Driver.Core.Operations.FindCommandOperation1.ExecuteAsync(RetryableReadContext context, CancellationToken cancellationToken)\n at MongoDB.Driver.Core.Operations.FindOperation1.ExecuteAsync(RetryableReadContext context, CancellationToken cancellationToken)\n at MongoDB.Driver.Core.Operations.FindOperation1.ExecuteAsync(IReadBinding binding, CancellationToken cancellationToken)\n at MongoDB.Driver.OperationExecutor.ExecuteReadOperationAsync[TResult](IReadBinding binding, IReadOperation1 operation, CancellationToken cancellationToken)\n at MongoDB.Driver.MongoCollectionImpl1.ExecuteReadOperationAsync[TResult](IClientSessionHandle session, IReadOperation1 operation, ReadPreference readPreference, CancellationToken cancellationToken)\n at MongoDB.Driver.MongoCollectionImpl1.UsingImplicitSessionAsync[TResult](Func2 funcAsync, CancellationToken cancellationToken)\n at MongoDB.Driver.IAsyncCursorSourceExtensions.ToListAsync[TDocument](IAsyncCursorSource1 source, CancellationToken cancellationToken)\n at Squidex.Domain.Apps.Entities.MongoDb.Contents.MongoContentCollection.QueryAsync(ISchemaEntity schema, ClrQuery query, List`1 ids, Status[] status, Boolean inDraft, Boolean includeDraft) in /src/src/Squidex.Domain.Apps.Entities.MongoDb/Contents/MongoContentCollection.cs:line 88\n at Squidex.Domain.Apps.Entities.MongoDb.Contents.MongoContentRepository.QueryAsync(IAppEntity app, ISchemaEntity schema, Status[] status, Boolean inDraft, ClrQuery query, Boolean includeDraft) in /src/src/Squidex.Domain.Apps.Entities.MongoDb/Contents/MongoContentRepository.cs:line 81\n at Squidex.Domain.Apps.Entities.Contents.Queries.ContentQueryService.QueryByQueryAsync(Context context, ISchemaEntity schema, Q query) in /src/src/Squidex.Domain.Apps.Entities/Contents/Queries/ContentQueryService.cs:line 301\n at Squidex.Domain.Apps.Entities.Contents.Queries.ContentQueryService.QueryAsync(Context context, String schemaIdOrName, Q query) in /src/src/Squidex.Domain.Apps.Entities/Contents/Queries/ContentQueryService.cs:line 114\n at Squidex.Domain.Apps.Entities.Contents.Queries.QueryExecutionContext.QueryContentsAsync(String schemaIdOrName, String query) in /src/src/Squidex.Domain.Apps.Entities/Contents/Queries/QueryExecutionContext.cs:line 85\n at GraphQL.Instrumentation.MiddlewareResolver.Resolve(ResolveFieldContext context)\n at Squidex.Domain.Apps.Entities.Contents.GraphQL.Middlewares.<>c__DisplayClass1_0.<b__1>d.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Contents/GraphQL/Middlewares.cs:line 51\n— End of stack trace from previous location where exception was thrown —\n at Squidex.Domain.Apps.Entities.Contents.GraphQL.Middlewares.<>c__DisplayClass0_1.<b__1>d.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Contents/GraphQL/Middlewares.cs:line 28"
},
“app”: {
“name”: “Squidex”,
“version”: “3.4.0.0”,
“sessionId”: “5b24e8a9-afe1-493a-8529-57acc3f7f866”
}

The issue appears after some number of successful attempts.

Expected behavior

Should return one document from the given collection.

Minimal reproduction of the problem

Tested a few times with different combinations of top/skip parameters and it stopped working after some number of successful queries:

working fine:

{
  queryEstatesContents(
    top: 1,
    skip: 205
  ) {
    id
  }
}

=>

{
  "data": {
    "queryEstatesContents": [
      {
        "id": "c9c81a82-695a-4f8d-8e71-9e01b7d9805c"
      }
    ]
  }
}

error:

{
  queryEstatesContents(
    top: 1,
    skip: 206
  ) {
    id
  }
}

=>

{
  "data": {
    "queryEstatesContents": null
  },
  "errors": [
    {
      "message": "Error trying to resolve queryEstatesContents.",
      "locations": [
        {
          "line": 2,
          "column": 3
        }
      ]
    }
  ]
}

Environment

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

Version: [3.4.0.0]

Browser:

[x] Chrome (desktop)
[ ] Chrome (Android)
[ ] Chrome (iOS)
[ ] Firefox
[ ] Safari (desktop)
[ ] Safari (iOS)
[ ] IE
[ ] Edge

Sebastian · May 21, 2020, 8:21am

I am not sure yet, if this is really a bug: https://docs.mongodb.com/manual/reference/limits/#Sort-Operations

It should work for the default order. You can try to turn on profiling and then have a log which queries are used without an index.

For your mongodb instance

db.setProfilingLevel(2)

alexmatskevich · May 21, 2020, 2:15pm

Thanks for your advice!
Yes, it was a Mongo error, there was no index for mt(lastModified) field. But I’m wondering, shouldn’t this index be created automatically? Does squidex have any interface for index creation?

Sebastian · May 21, 2020, 2:17pm

Yes, this is strange, the indexes should be created automatically.’

github.com

Squidex/squidex/blob/master/backend/src/Squidex.Domain.Apps.Entities.MongoDb/Contents/Operations/QueryContentsByQuery.cs#L42


    this.indexer = indexer;
}


protected override Task PrepareAsync(CancellationToken ct = default)
{
    var index =
        new CreateIndexModel<MongoContentEntity>(Index
            .Ascending(x => x.IndexedSchemaId)
            .Ascending(x => x.IsDeleted)
            .Ascending(x => x.ReferencedIds)
            .Descending(x => x.LastModified));


    return Collection.Indexes.CreateOneAsync(index, cancellationToken: ct);
}


public async Task<IResultList<IContentEntity>> DoAsync(IAppEntity app, ISchemaEntity schema, ClrQuery query, SearchScope scope)
{
    Guard.NotNull(app, nameof(app));
    Guard.NotNull(schema, nameof(schema));
    Guard.NotNull(query, nameof(query));

Perhaps there is a bug that causes the method not be called or so…

Sebastian · May 22, 2020, 7:42am

I think I can also bypass this issue for other sort directions where an index does not exist.

The idea is to use the aggregation framework and to make 2 queries:

gist.github.com

https://gist.github.com/SebastianStehle/db55773603b88c71d466d14f7a39bfce

Test.cs

using LoremNET;
using MongoDB.Bson;
using MongoDB.Driver;
using System;
using System.Diagnostics;
using System.Linq;

namespace ConsoleApp6
{
    class Program

This file has been truncated. show original

Sebastian · June 8, 2020, 4:32pm

I have made an improvement to fix that or at least make it less likely to happen.

Sebastian · June 8, 2020, 4:32pm