DomainObjectNotFoundException during restore

mvacha · December 6, 2019, 11:03am

I have…

[X] Checked the logs and have provided 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

Restore fails with an error and everything seems to be is restored properly (assets, rules, schemas, content, but the app does not show up until I log out and log in again.

Log:

{
  "logLevel": "Error",
  "action": "GrainInvoked",
  "status": "Failed",
  "grain": "Squidex.Domain.Apps.Entities.Apps.AppGrain",
  "grainMethod": "System.Threading.Tasks.Task\u00601[Squidex.Infrastructure.Orleans.J\u00601[System.Object]] ExecuteAsync(Squidex.Infrastructure.Orleans.J\u00601[Squidex.Infrastructure.Commands.IAggregateCommand])",
  "exception": {
    "type": "Squidex.Infrastructure.DomainObjectNotFoundException",
    "message": "Domain object \u00275de9ad31e5588a00013b47ba\u0027 not found on Squidex.Domain.Apps.Entities.Apps.IAppEntity.Contributors",
    "stackTrace": "   at Squidex.Domain.Apps.Entities.Apps.Guards.GuardAppContributors.\u003C\u003Ec__DisplayClass0_0.\u003C\u003CCanAssign\u003Eb__1\u003Ed.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Apps/Guards/GuardAppContributors.cs:line 46\n--- End of stack trace from previous location where exception was thrown ---\n   at Squidex.Infrastructure.Validation.Validate.It(Func\u00601 message, Func\u00602 action) in /src/src/Squidex.Infrastructure/Validation/Validate.cs:line 54\n   at Squidex.Domain.Apps.Entities.Apps.AppGrain.\u003C\u003Ec__DisplayClass5_0.\u003C\u003CExecuteAsync\u003Eb__4\u003Ed.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Apps/AppGrain.cs:line 107\n--- End of stack trace from previous location where exception was thrown ---\n   at Squidex.Infrastructure.Commands.DomainObjectGrainBase\u00601.InvokeAsync[TCommand](TCommand command, Func\u00602 handler, Mode mode) in /src/src/Squidex.Infrastructure/Commands/DomainObjectGrainBase.cs:line 177\n   at Squidex.Infrastructure.Commands.DomainObjectGrainBase\u00601.ExecuteAsync(J\u00601 command) in /src/src/Squidex.Infrastructure/Commands/DomainObjectGrainBase.cs:line 219\n   at Squidex.Domain.Apps.Entities.Apps.OrleansCodeGenAppGrainMethodInvoker.Invoke(IAddressable grain, InvokeMethodRequest request) in /src/src/Squidex.Domain.Apps.Entities/obj/Release/netcoreapp3.0/Squidex.Domain.Apps.Entities.orleans.g.cs:line 35\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.StateFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/StateFilter.cs:line 27\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.LoggingFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/LoggingFilter.cs:line 46"
  },
  "app": {
    "name": "Squidex",
    "version": "4.0.3.0",
    "sessionId": "6fb6e75b-5183-4c15-a7b6-b3164adf5665"
  },
  "timestamp": "2019-12-06T10:42:21Z"
}

{
  "logLevel": "Error",
  "action": "retore",
  "status": "failed",
  "operationId": "f412521b-fd23-4f4c-91e5-24b14d834c9a",
  "url": "https://fiddodevcdn.blob.core.windows.net/media/backup-magazine-2019-12-06_10-38-30.zip",
  "profiler": {
    "BackupApps/CompleteRestoreAsync": {
      "elapsedMsTotal": 115,
      "elapsedMsAvg": 115,
      "count": 1
    },
    "MongoEventStore/AppendAsync": {
      "elapsedMsTotal": 2209,
      "elapsedMsAvg": 49,
      "count": 45
    },
    "BackupRules/CompleteRestoreAsync": {
      "elapsedMsTotal": 0,
      "elapsedMsAvg": 0,
      "count": 1
    },
    "BackupRules/RestoreAsync": {
      "elapsedMsTotal": 95,
      "elapsedMsAvg": 95,
      "count": 1
    },
    "MongoContentRepository/WriteAsync": {
      "elapsedMsTotal": 596,
      "elapsedMsAvg": 119,
      "count": 5
    },
    "BackupAssets/RestoreAsync": {
      "elapsedMsTotal": 229,
      "elapsedMsAvg": 229,
      "count": 1
    },
    "ReadEvents": {
      "elapsedMsTotal": 2887,
      "elapsedMsAvg": 2887,
      "count": 1
    },
    "MongoContentRepository/ReadAsync": {
      "elapsedMsTotal": 12,
      "elapsedMsAvg": 2,
      "count": 5
    },
    "MongoAssetRepository/ReadAsync": {
      "elapsedMsTotal": 6,
      "elapsedMsAvg": 2,
      "count": 3
    },
    "MongoSnapshotStore\u00602/WriteAsync": {
      "elapsedMsTotal": 433,
      "elapsedMsAvg": 72,
      "count": 6
    },
    "BackupContents/RestoreAsync": {
      "elapsedMsTotal": 643,
      "elapsedMsAvg": 643,
      "count": 1
    },
    "BackupAssets/CompleteRestoreAsync": {
      "elapsedMsTotal": 0,
      "elapsedMsAvg": 0,
      "count": 1
    },
    "BackupSchemas/RestoreAsync": {
      "elapsedMsTotal": 96,
      "elapsedMsAvg": 96,
      "count": 1
    },
    "MongoAssetRepository/WriteAsync": {
      "elapsedMsTotal": 56,
      "elapsedMsAvg": 18,
      "count": 3
    },
    "MongoEventStore/QueryAsync": {
      "elapsedMsTotal": 36,
      "elapsedMsAvg": 3,
      "count": 12
    },
    "Download": {
      "elapsedMsTotal": 148,
      "elapsedMsAvg": 148,
      "count": 1
    },
    "BackupContents/CompleteRestoreAsync": {
      "elapsedMsTotal": 0,
      "elapsedMsAvg": 0,
      "count": 1
    },
    "SchemasIndex/GetSchemaAsync": {
      "elapsedMsTotal": 58,
      "elapsedMsAvg": 19,
      "count": 3
    },
    "BackupSchemas/CompleteRestoreAsync": {
      "elapsedMsTotal": 0,
      "elapsedMsAvg": 0,
      "count": 1
    },
    "BackupApps/RestoreAsync": {
      "elapsedMsTotal": 105,
      "elapsedMsAvg": 105,
      "count": 1
    },
    "MongoSnapshotStore\u00602/ReadAsync": {
      "elapsedMsTotal": 42,
      "elapsedMsAvg": 5,
      "count": 8
    }
  },
  "exception": {
    "type": "Squidex.Infrastructure.DomainObjectNotFoundException",
    "message": "Domain object \u00275de9ad31e5588a00013b47ba\u0027 not found on Squidex.Domain.Apps.Entities.Apps.IAppEntity.Contributors",
    "stackTrace": "   at Squidex.Domain.Apps.Entities.Apps.Guards.GuardAppContributors.\u003C\u003Ec__DisplayClass0_0.\u003C\u003CCanAssign\u003Eb__1\u003Ed.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Apps/Guards/GuardAppContributors.cs:line 46\n--- End of stack trace from previous location where exception was thrown ---\n   at Squidex.Infrastructure.Validation.Validate.It(Func\u00601 message, Func\u00602 action) in /src/src/Squidex.Infrastructure/Validation/Validate.cs:line 54\n   at Squidex.Domain.Apps.Entities.Apps.AppGrain.\u003C\u003Ec__DisplayClass5_0.\u003C\u003CExecuteAsync\u003Eb__4\u003Ed.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Apps/AppGrain.cs:line 107\n--- End of stack trace from previous location where exception was thrown ---\n   at Squidex.Infrastructure.Commands.DomainObjectGrainBase\u00601.InvokeAsync[TCommand](TCommand command, Func\u00602 handler, Mode mode) in /src/src/Squidex.Infrastructure/Commands/DomainObjectGrainBase.cs:line 177\n   at Squidex.Infrastructure.Commands.DomainObjectGrainBase\u00601.ExecuteAsync(J\u00601 command) in /src/src/Squidex.Infrastructure/Commands/DomainObjectGrainBase.cs:line 219\n   at Squidex.Domain.Apps.Entities.Apps.OrleansCodeGenAppGrainMethodInvoker.Invoke(IAddressable grain, InvokeMethodRequest request) in /src/src/Squidex.Domain.Apps.Entities/obj/Release/netcoreapp3.0/Squidex.Domain.Apps.Entities.orleans.g.cs:line 35\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.StateFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/StateFilter.cs:line 27\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.LoggingFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/LoggingFilter.cs:line 46\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.LocalCacheFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/LocalCacheFilter.cs:line 39\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at OrleansDashboard.Metrics.GrainProfilerFilter.Invoke(IIncomingGrainCallContext context)\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Orleans.Runtime.InsideRuntimeClient.Invoke(IAddressable target, IInvokable invokable, Message message)\n   at Orleans.Internal.OrleansTaskExtentions.\u003CToTypedTask\u003Eg__ConvertAsync|4_0[T](Task\u00601 asyncTask)\n   at Squidex.Infrastructure.Commands.GrainCommandMiddleware\u00602.ExecuteCommandAsync(TCommand typedCommand) in /src/src/Squidex.Infrastructure/Commands/GrainCommandMiddleware.cs:line 46\n   at Squidex.Infrastructure.Commands.GrainCommandMiddleware\u00602.ExecuteCommandAsync(CommandContext context) in /src/src/Squidex.Infrastructure/Commands/GrainCommandMiddleware.cs:line 36\n   at Squidex.Domain.Apps.Entities.Apps.AppCommandMiddleware.HandleAsync(CommandContext context, Func\u00601 next) in /src/src/Squidex.Domain.Apps.Entities/Apps/AppCommandMiddleware.cs:line 50\n   at Squidex.Domain.Apps.Entities.Schemas.Indexes.SchemasIndex.HandleAsync(CommandContext context, Func\u00601 next) in /src/src/Squidex.Domain.Apps.Entities/Schemas/Indexes/SchemasIndex.cs:line 128\n   at Squidex.Domain.Apps.Entities.Rules.Indexes.RulesIndex.HandleAsync(CommandContext context, Func\u00601 next) in /src/src/Squidex.Domain.Apps.Entities/Rules/Indexes/RulesIndex.cs:line 77\n   at Squidex.Domain.Apps.Entities.Apps.Indexes.AppsIndex.HandleAsync(CommandContext context, Func\u00601 next) in /src/src/Squidex.Domain.Apps.Entities/Apps/Indexes/AppsIndex.cs:line 200\n   at Squidex.Domain.Apps.Entities.Apps.Invitation.InviteUserCommandMiddleware.HandleAsync(CommandContext context, Func\u00601 next) in /src/src/Squidex.Domain.Apps.Entities/Apps/Invitation/InviteUserCommandMiddleware.cs:line 43\n   at Squidex.Infrastructure.Commands.CustomCommandMiddlewareRunner.HandleAsync(CommandContext context, Func\u00601 next) in /src/src/Squidex.Infrastructure/Commands/CustomCommandMiddlewareRunner.cs:line 33\n   at Squidex.Web.CommandMiddlewares.EnrichWithSchemaIdCommandMiddleware.HandleAsync(CommandContext context, Func\u00601 next) in /src/src/Squidex.Web/CommandMiddlewares/EnrichWithSchemaIdCommandMiddleware.cs:line 54\n   at Squidex.Web.CommandMiddlewares.ETagCommandMiddleware.HandleAsync(CommandContext context, Func\u00601 next) in /src/src/Squidex.Web/CommandMiddlewares/ETagCommandMiddleware.cs:line 34\n   at Squidex.Infrastructure.Commands.InMemoryCommandBus.PublishAsync(ICommand command) in /src/src/Squidex.Infrastructure/Commands/InMemoryCommandBus.cs:line 42\n   at Squidex.Domain.Apps.Entities.Backup.RestoreGrain.AssignContributorAsync() in /src/src/Squidex.Domain.Apps.Entities/Backup/RestoreGrain.cs:line 262\n   at Squidex.Domain.Apps.Entities.Backup.RestoreGrain.ProcessAsync() in /src/src/Squidex.Domain.Apps.Entities/Backup/RestoreGrain.cs:line 197"
  },
  "app": {
    "name": "Squidex",
    "version": "4.0.3.0",
    "sessionId": "6fb6e75b-5183-4c15-a7b6-b3164adf5665"
  },
  "timestamp": "2019-12-06T10:42:21Z"
}

Expected behavior

No error

Minimal reproduction of the problem

restore this file: https://www.dropbox.com/s/7xvo1vezagldp2o/backup-magazine-2019-12-06_10-38-30.zip?dl=0
error shows up and there is no app visible in squidex
log out
log in (with the same account), the app shows up and seems “fine”.

Environment

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

Version: 4.0.3 (latest available on docker hub)

Browser:

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

Other Information

Related issue: [SOLVED] DomainObjectNotFoundException during restore

Sebastian · December 6, 2019, 11:12am

Thx, I will have a look.

Sebastian · December 6, 2019, 12:10pm

I cannot reproduce it, perhaps because I was not an owner before…

I also backed up your app and restored it with another name: Works as well.

mvacha · December 6, 2019, 1:33pm

Ok, I’ll try to reproduce it once again and provide you with a better repro.

Sebastian · December 6, 2019, 5:42pm

How have you restored the app? With a client or as a user?

Do you have a custom identity server or so?

The reason I ask: This error occurs when the user who triggered the restore is added as a contributor to the app itself. So somehow the id must have been invalid.

mvacha · December 7, 2019, 12:44am

My goal was to migrate an existing app to from an old mongo atlas cluster to a new one.
I took this steps:
When the app was still connected to a cluster #1:

logged in as an admin to the web interface
started a backup and downloaded it after it was created
uploaded the backup to azure storage
deployed a new k8s configuration of squidex with mongo connection string modified to cluster #2.
logged in to the web interface and performed a restore from azure storage public url.

And I use the standard Squidex Identity Server.

Sebastian · December 7, 2019, 8:52am

My assumption is the following:

You created your new cluster under the same domain and the token was still valid. Therefore you are kind of logged in to the new cluster but with an old user id.

When your restored the backup the backup process tried to invite you to the new app with the old id, which failed in this case. This was also the reason you were not able to see the new app.

After you logged out and logged in again you could see the new app because your token had the new id.

In this case it is a weird behavior that is hard to solve, but not a bug to worry about.

mvacha · December 7, 2019, 11:53pm

You are right - the new cluster was exactly the same as the old one except for two environmental variables (mongo connection strings).

I agree that the error+relogin is just a weird behavior that happens in this particular edge case, so you can close this issue.