Mongo error after upgrade to 5.7.0

ben · June 24, 2021, 2:39pm

I have…

[x ] Read the following guideline: https://docs.squidex.io/01-getting-started/installation/troubleshooting-and-support. I understand that my support request might get deleted if I do not follow the guideline.

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

After upgrading from 5.4.0 to 5.7.0 no content appears when viewing any schema in the content section. When trying to rebuild consumers (e.g. the TextIndexer5) an error occurs:

MongoDB.Driver.MongoCommandException: Command aggregate failed: Resume of change stream was not possible, as the resume point may no longer be in the oplog…
at MongoDB.Driver.Core.WireProtocol.CommandUsingCommandMessageWireProtocol1.ProcessResponse(ConnectionId connectionId, CommandMessage responseMessage) at MongoDB.Driver.Core.WireProtocol.CommandUsingCommandMessageWireProtocol1.Execute(IConnection connection, CancellationToken cancellationToken)
at MongoDB.Driver.Core.WireProtocol.CommandWireProtocol1.Execute(IConnection connection, CancellationToken cancellationToken) at MongoDB.Driver.Core.Servers.Server.ServerChannel.ExecuteProtocol[TResult](IWireProtocol1 protocol, ICoreSession session, CancellationToken cancellationToken)
at MongoDB.Driver.Core.Servers.Server.ServerChannel.Command[TResult](ICoreSession session, ReadPreference readPreference, DatabaseNamespace databaseNamespace, BsonDocument command, IEnumerable1 commandPayloads, IElementNameValidator commandValidator, BsonDocument additionalOptions, Action1 postWriteAction, CommandResponseHandling responseHandling, IBsonSerializer1 resultSerializer, MessageEncoderSettings messageEncoderSettings, CancellationToken cancellationToken) at MongoDB.Driver.Core.Operations.CommandOperationBase1.ExecuteProtocol(IChannelHandle channel, ICoreSessionHandle session, ReadPreference readPreference, CancellationToken cancellationToken)
at MongoDB.Driver.Core.Operations.ReadCommandOperation1.ExecuteAttempt(RetryableReadContext context, Int32 attempt, Nullable1 transactionNumber, CancellationToken cancellationToken)
at MongoDB.Driver.Core.Operations.RetryableReadOperationExecutor.Execute[TResult](IRetryableReadOperation1 operation, RetryableReadContext context, CancellationToken cancellationToken) at MongoDB.Driver.Core.Operations.ReadCommandOperation1.Execute(RetryableReadContext context, CancellationToken cancellationToken)
at MongoDB.Driver.Core.Operations.AggregateOperation1.Execute(RetryableReadContext context, CancellationToken cancellationToken) at MongoDB.Driver.Core.Operations.ChangeStreamOperation1.Execute(IReadBinding binding, CancellationToken cancellationToken)
at MongoDB.Driver.OperationExecutor.ExecuteReadOperation[TResult](IReadBinding binding, IReadOperation1 operation, CancellationToken cancellationToken) at MongoDB.Driver.MongoCollectionImpl1.ExecuteReadOperation[TResult](IClientSessionHandle session, IReadOperation1 operation, ReadPreference readPreference, CancellationToken cancellationToken) at MongoDB.Driver.MongoCollectionImpl1.ExecuteReadOperation[TResult](IClientSessionHandle session, IReadOperation1 operation, CancellationToken cancellationToken) at MongoDB.Driver.MongoCollectionImpl1.Watch[TResult](IClientSessionHandle session, PipelineDefinition2 pipeline, ChangeStreamOptions options, CancellationToken cancellationToken) at MongoDB.Driver.MongoCollectionImpl1.<>c__DisplayClass66_01.<Watch>b__0(IClientSessionHandle session) at MongoDB.Driver.MongoCollectionImpl1.UsingImplicitSession[TResult](Func2 func, CancellationToken cancellationToken) at MongoDB.Driver.MongoCollectionImpl1.Watch[TResult](PipelineDefinition`2 pipeline, ChangeStreamOptions options, CancellationToken cancellationToken)
at Squidex.Infrastructure.EventSourcing.MongoEventStoreSubscription.QueryCurrentAsync(String streamFilter, StreamPosition lastPosition)
at Squidex.Infrastructure.EventSourcing.MongoEventStoreSubscription.QueryAsync(String streamFilter, String position) in /src/src/Squidex.Infrastructure.MongoDb/EventSourcing/MongoEventStoreSubscription.cs:line 55

Expected behavior

Content is available as prior to upgrade and consumers work.

Minimal reproduction of the problem

Environment

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

Hosted in Cloudfoundry usingdotnetcore buildpack

Version: 5.7.0

Browser:

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

Others:

I have rolled back the database and performed several times and always results in this issue.
There are no errors in the logs - I only see the above error on the frontend next to a consumer when it is not working
We have mongo DB atlas v4.2.14

Sebastian · June 24, 2021, 2:45pm

Have you tried a restart? if it does not help you can send me the backup of your database.

ben · June 25, 2021, 1:45pm

I tried a restart but this did not help. I have tried various things with the Mongo DB such as increasing the Oplog size and trying the upgrade on another environment and the same issue occurs.

I am unsure whether the error is just a result of a different issue, but I have no other errors in the logs.

I did notice that despite no content showing, I am able to add new content. I also noticed that my new content seems to go into a new collection called “States_Contents_All3”, all my old content is associated with “States_Contents_All2”, is there meant to be a migration process?

Unfortunately I am unable to share the database due to our clients data policies

Sebastian · June 25, 2021, 1:58pm

Yes, there should be a migration process. Perhaps it has been interrupted somehow. The version is stored in a migration collection.

ben · June 25, 2021, 2:16pm

_id:“Default”
IsLocked:false
Version:25

There is nothing obvious in the logs when the migration steps happen.

{
“logLevel”: “Information”,
“initializedSystem”: “CreateAdminInitializer”,
“timestamp”: “2021-06-25T13:14:28Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Warning”,
“message”: “Task [Id=1, Status=RanToCompletion] in WorkGroup [LowPrioritySystemTarget: S127.0.0.1:11111:362322862stg/Orleans.Runtime.ReminderService.LocalReminderService/00000000@S00000000] took elapsed time 0:00:00.3177124 for execution, which is longer than 00:00:00.2000000. Running on thread 10",
“eventId”: {
“id”: 101215
},
“task”: “[Id=1, Status=RanToCompletion]”,
“grainContext”: "[LowPrioritySystemTarget: S127.0.0.1:11111:362322862stg/Orleans.Runtime.ReminderService.LocalReminderService/00000000@S00000000]”,
“duration”: “0:00:00.3177124”,
“turnWarningLengthThreshold”: “00:00:00.2000000”,
“thread”: “10”,
“timestamp”: “2021-06-25T13:14:28Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
},
“category”: “Orleans.Runtime.Scheduler.WorkItemGroup”
}

{
“logLevel”: “Information”,
“action”: “Migration”,
“status”: “Started”,
“migrator”: “Migrations.Migrations.StopEventConsumers”,
“timestamp”: “2021-06-25T13:14:29Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Information”,
“action”: “Migration”,
“status”: “Completed”,
“migrator”: “Migrations.Migrations.StopEventConsumers”,
“elapsedMs”: 466,
“timestamp”: “2021-06-25T13:14:29Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Information”,
“action”: “Migration”,
“status”: “Started”,
“migrator”: “Migrations.Migrations.RebuildApps”,
“timestamp”: “2021-06-25T13:14:29Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Information”,
“action”: “Migration”,
“status”: “Completed”,
“migrator”: “Migrations.Migrations.RebuildApps”,
“elapsedMs”: 571,
“timestamp”: “2021-06-25T13:14:30Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Information”,
“action”: “Migration”,
“status”: “Started”,
“migrator”: “Migrations.Migrations.RebuildContents”,
“timestamp”: “2021-06-25T13:14:30Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Information”,
“action”: “ActivateDomainObject”,
“domainObjectType”: “SchemaDomainObject”,
“domainObjectKey”: “1427b085-aee7-4a90-ad38-5146c419d923–0876aae2-7ec6-461e-99dc-9b0979f0a442”,
“elapsedMs”: 374,
“timestamp”: “2021-06-25T13:14:31Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Information”,
“action”: “Migration”,
“status”: “Completed”,
“migrator”: “Migrations.Migrations.RebuildContents”,
“elapsedMs”: 1306,
“timestamp”: “2021-06-25T13:14:31Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Information”,
“action”: “Migration”,
“status”: “Started”,
“migrator”: “Migrations.Migrations.StartEventConsumers”,
“timestamp”: “2021-06-25T13:14:31Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

{
“logLevel”: “Information”,
“action”: “Migration”,
“status”: “Completed”,
“migrator”: “Migrations.Migrations.StartEventConsumers”,
“elapsedMs”: 155,
“timestamp”: “2021-06-25T13:14:31Z”,
“app”: {
“name”: “Squidex”,
“version”: “5.7.0.0”,
“sessionId”: “aaa2f287-4f0f-4d6f-bf8b-6c9645c73a56”
}
}

Sebastian · June 25, 2021, 2:26pm

how many content items do you have in total?

Btw: Please use code blocks to format log files / samples.

ben · June 25, 2021, 2:28pm

The States_Contents_All2 Collection has:
COLLECTION SIZE: 27.01MB
TOTAL DOCUMENTS: 21473
INDEXES TOTAL SIZE: 8.02MB

Sebastian · June 25, 2021, 2:34pm

Okay. The contents collection cannot migrate within 1.7sec, no chance. You have 3 options now:

You provide me the backup.
You try to reproduce it yourself.
We make a support contract so that I can support directly.

I will try to reproduce it as well, but I have no crystal ball.

ben · June 25, 2021, 3:42pm

I can see code in the migrations that migrates from the original State_Contents_All to States_Content_All2 but I can’t see where it migrates it further to State_Content_All3.

Am I missing something? My content successfully migrated to State_Content_All2 when upgrading previously.

I will have to see what we can do about providing a DB backup. I will need to speak to some people.

ben · June 25, 2021, 3:58pm

I have rerun the migration again and I can see one item in the State_Content_All3 collection. I don’t really know what the item is but it has
ai:Object
_id: "xxxxxxxxxxxxxxx"
name: "a previously archived app"

It could be an issue with migrating archived apps? It’s a pure guess but potentially something not tested.

Sebastian · June 25, 2021, 4:26pm

The migration works by just rebuilding the content and because the name of the content collection has been changed to State_Contents3 the new collection gets populated.

ben · June 28, 2021, 9:27am

I have been able to send you a message with a link to a database backup.

Sebastian · June 28, 2021, 11:24am

Please use mongorestore for your backup.

Which docker version have you used?

ben · June 28, 2021, 1:43pm

Mongo is hosted in Atlas and I provided the backup file they give. I am re-exporting using mongodump and will provide when finished.

The app is hosted in cloudfoundry using a nodejs buildpack (https://docs.cloudfoundry.org/buildpacks/node/index.html) and directly deploying the binaries for the release.

Sebastian · June 28, 2021, 1:47pm

But which version of atlas? I think my docker version is incompatible.

ben · June 28, 2021, 1:59pm

The Mongo Atlas version is 4.2.14

Sebastian · June 28, 2021, 2:30pm

This also give me wired tiger compatibility issues.

ben · June 28, 2021, 2:33pm

I have sent you mongodump versions in case this helps.

Sebastian · June 28, 2021, 4:03pm

I have imported the dump and I am running it with the latest dev version and it works totally fine.

I am trying 5.7.0 now but the chances are high that I cannot reproduce it.

UPDATE: I can reproduce the error with 5.7.0. But the problem is a bug that was fixed with 5.7.1

ben · June 29, 2021, 6:47am

Thank you for identifying the issue Sebastian. I didn’t use the 5.7.1 release as there were no binaries available and I don’t have the right set up currently to build the source. I see you have released 5.8.0 this morning so will try upgrading to that instead.