[SOLVED] DomainObjectNotFoundException during restore

spacecat · May 3, 2019, 12:32pm

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

Tried restoring an app (zip) from a URL but ended up with:

2019-05-03T12:20:00Z: Started. The restore process has the following steps:
2019-05-03T12:20:00Z: * Download backup
2019-05-03T12:20:00Z: * Restore events and attachments.
2019-05-03T12:20:00Z: * Restore all objects like app, schemas and contents
2019-05-03T12:20:00Z: * Complete the restore operation for all objects
2019-05-03T12:20:00Z: Downloading Backup
2019-05-03T12:20:01Z: Reading 125 events and 1 attachments completed.
2019-05-03T12:20:01Z: Restored Apps
2019-05-03T12:20:02Z: Restored Assets
2019-05-03T12:20:04Z: Restored Contents
2019-05-03T12:20:04Z: Restored Rules
2019-05-03T12:20:04Z: Restored Schemas
2019-05-03T12:20:04Z: Completed Apps
2019-05-03T12:20:04Z: Completed Assets
2019-05-03T12:20:04Z: Completed Contents
2019-05-03T12:20:04Z: Completed Rules
2019-05-03T12:20:04Z: Completed Schemas
2019-05-03T12:20:04Z: Failed with internal error

Expected behavior

The restore should have completed successfully.

Minimal reproduction of the problem

Just restore a zip from a URL.

Environment

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

Version: I pulled the latest squidex:dev image minutes ago so I think it’s this one:
dev-2236 60 MB

Browser:

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

Others:

Logs below:

squidex_squidex_1  | {
squidex_squidex_1  |   "logLevel": "Error",
squidex_squidex_1  |   "action": "GrainInvoked",
squidex_squidex_1  |   "status": "Failed",
squidex_squidex_1  |   "grain": "Squidex.Domain.Apps.Entities.Apps.AppGrain",
squidex_squidex_1  |   "grainMethod": "System.Threading.Tasks.Task`1[Squidex.Infrastructure.Orleans.J`1[System.Object]] ExecuteAsync(Squidex.Infrastructure.Orleans.J`1[Squidex.Infrastructure.Commands.IAggregateCommand])",
squidex_squidex_1  |   "exception": {
squidex_squidex_1  |     "type": "Squidex.Infrastructure.DomainObjectNotFoundException",
squidex_squidex_1  |     "message": "Domain object '5c9bdba96ea15a000190a67f' not found on Squidex.Domain.Apps.Entities.Apps.IAppEntity.Contributors",
squidex_squidex_1  |     "stackTrace": "   at Squidex.Domain.Apps.Entities.Apps.Guards.GuardAppContributors.<>c__DisplayClass0_0.<<CanAssign>b__1>d.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Apps/Guards/GuardAppContributors.cs:line 42\n--- End of stack trace from previous location where exception was thrown ---\n   at Squidex.Infrastructure.Validate.It(Func`1 message, Func`2 action) in /src/src/Squidex.Infrastructure/Validate.cs:line 56\n   at Squidex.Domain.Apps.Entities.Apps.AppGrain.<>c__DisplayClass5_0.<<ExecuteAsync>b__1>d.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Apps/AppGrain.cs:line 75\n--- End of stack trace from previous location where exception was thrown ---\n   at Squidex.Infrastructure.Commands.DomainObjectGrainBase`1.InvokeAsync[TCommand](TCommand command, Func`2 handler, Mode mode) in /src/src/Squidex.Infrastructure/Commands/DomainObjectGrainBase.cs:line 182\n   at Squidex.Infrastructure.Commands.DomainObjectGrainBase`1.ExecuteAsync(J`1 command) in /src/src/Squidex.Infrastructure/Commands/DomainObjectGrainBase.cs:line 224\n   at Squidex.Domain.Apps.Entities.Apps.OrleansCodeGenAppGrainMethodInvoker.Invoke(IAddressable grain, InvokeMethodRequest request) in /src/src/Squidex.Domain.Apps.Entities/obj/Release/netstandard2.0/Squidex.Domain.Apps.Entities.orleans.g.cs:line 35\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at OrleansDashboard.Metrics.GrainProfiler.Invoke(IIncomingGrainCallContext context)\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.LoggingFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/LoggingFilter.cs:line 30"
squidex_squidex_1  |   },
squidex_squidex_1  |   "app": {
squidex_squidex_1  |     "name": "Squidex",
squidex_squidex_1  |     "version": "1.0.0.0",
squidex_squidex_1  |     "sessionId": "3dcc509e-ef36-4d98-bab6-354ac8cbc276"
squidex_squidex_1  |   },
squidex_squidex_1  |   "timestamp": "2019-05-03T12:20:04Z"
squidex_squidex_1  | }
squidex_squidex_1  |
squidex_squidex_1  | {
squidex_squidex_1  |   "logLevel": "Error",
squidex_squidex_1  |   "action": "retore",
squidex_squidex_1  |   "status": "failed",
squidex_squidex_1  |   "operationId": "259cba36-f579-4587-8551-8954286dacc6",
squidex_squidex_1  |   "url": "https://url.to/Backup.zip",
squidex_squidex_1  |   "profiler": {
squidex_squidex_1  |     "Download": {
squidex_squidex_1  |       "elapsedMsTotal": 301,
squidex_squidex_1  |       "elapsedMsAvg": 301,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "mongoSnapshotStore`2/WriteAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 42,
squidex_squidex_1  |       "elapsedMsAvg": 7,
squidex_squidex_1  |       "count": 6
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupSchemas/RestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 5,
squidex_squidex_1  |       "elapsedMsAvg": 5,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "mongoSnapshotStore`2/ReadAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 26,
squidex_squidex_1  |       "elapsedMsAvg": 4,
squidex_squidex_1  |       "count": 6
squidex_squidex_1  |     },
squidex_squidex_1  |     "mongoEventStore/QueryAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 898,
squidex_squidex_1  |       "elapsedMsAvg": 1,
squidex_squidex_1  |       "count": 585
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupContents/CompleteRestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 0,
squidex_squidex_1  |       "elapsedMsAvg": 0,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupAssets/RestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 1307,
squidex_squidex_1  |       "elapsedMsAvg": 1307,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "mongoEventStore/AppendAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 726,
squidex_squidex_1  |       "elapsedMsAvg": 5,
squidex_squidex_1  |       "count": 125
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupRules/CompleteRestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 0,
squidex_squidex_1  |       "elapsedMsAvg": 0,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "ReadEvents": {
squidex_squidex_1  |       "elapsedMsTotal": 984,
squidex_squidex_1  |       "elapsedMsAvg": 984,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupApps/CompleteRestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 7,
squidex_squidex_1  |       "elapsedMsAvg": 7,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupRules/RestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 3,
squidex_squidex_1  |       "elapsedMsAvg": 3,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "mongoAssetRepository/ReadAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 592,
squidex_squidex_1  |       "elapsedMsAvg": 3,
squidex_squidex_1  |       "count": 191
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupApps/RestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 24,
squidex_squidex_1  |       "elapsedMsAvg": 24,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupAssets/CompleteRestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 0,
squidex_squidex_1  |       "elapsedMsAvg": 0,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "appProvider/GetSchemaAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 13,
squidex_squidex_1  |       "elapsedMsAvg": 3,
squidex_squidex_1  |       "count": 4
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupContents/RestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 1296,
squidex_squidex_1  |       "elapsedMsAvg": 1296,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "mongoContentRepository/ReadAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 490,
squidex_squidex_1  |       "elapsedMsAvg": 1,
squidex_squidex_1  |       "count": 391
squidex_squidex_1  |     },
squidex_squidex_1  |     "backupSchemas/CompleteRestoreAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 0,
squidex_squidex_1  |       "elapsedMsAvg": 0,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "mongoContentRepository/WriteAsync": {
squidex_squidex_1  |       "elapsedMsTotal": 17,
squidex_squidex_1  |       "elapsedMsAvg": 8,
squidex_squidex_1  |       "count": 2
squidex_squidex_1  |     }
squidex_squidex_1  |   },
squidex_squidex_1  |   "exception": {
squidex_squidex_1  |     "type": "Squidex.Infrastructure.DomainObjectNotFoundException",
squidex_squidex_1  |     "message": "Domain object '5c9bdba96ea15a000190a67f' not found on Squidex.Domain.Apps.Entities.Apps.IAppEntity.Contributors",
squidex_squidex_1  |     "stackTrace": "   at Squidex.Domain.Apps.Entities.Apps.Guards.GuardAppContributors.<>c__DisplayClass0_0.<<CanAssign>b__1>d.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Apps/Guards/GuardAppContributors.cs:line 42\n--- End of stack trace from previous location where exception was thrown ---\n   at Squidex.Infrastructure.Validate.It(Func`1 message, Func`2 action) in /src/src/Squidex.Infrastructure/Validate.cs:line 56\n   at Squidex.Domain.Apps.Entities.Apps.AppGrain.<>c__DisplayClass5_0.<<ExecuteAsync>b__1>d.MoveNext() in /src/src/Squidex.Domain.Apps.Entities/Apps/AppGrain.cs:line 75\n--- End of stack trace from previous location where exception was thrown ---\n   at Squidex.Infrastructure.Commands.DomainObjectGrainBase`1.InvokeAsync[TCommand](TCommand command, Func`2 handler, Mode mode) in /src/src/Squidex.Infrastructure/Commands/DomainObjectGrainBase.cs:line 182\n   at Squidex.Infrastructure.Commands.DomainObjectGrainBase`1.ExecuteAsync(J`1 command) in /src/src/Squidex.Infrastructure/Commands/DomainObjectGrainBase.cs:line 224\n   at Squidex.Domain.Apps.Entities.Apps.OrleansCodeGenAppGrainMethodInvoker.Invoke(IAddressable grain, InvokeMethodRequest request) in /src/src/Squidex.Domain.Apps.Entities/obj/Release/netstandard2.0/Squidex.Domain.Apps.Entities.orleans.g.cs:line 35\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at OrleansDashboard.Metrics.GrainProfiler.Invoke(IIncomingGrainCallContext context)\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.LoggingFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/LoggingFilter.cs:line 30\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.LocalCacheFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/LocalCacheFilter.cs:line 32\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Orleans.Runtime.InsideRuntimeClient.Invoke(IAddressable target, IInvokable invokable, Message message)\n   at Orleans.OrleansTaskExtentions.<ToTypedTask>g__ConvertAsync|4_0[T](Task`1 asyncTask)\n   at Squidex.Infrastructure.Commands.GrainCommandMiddleware`2.ExecuteCommandAsync(TCommand typedCommand) in /src/src/Squidex.Infrastructure/Commands/GrainCommandMiddleware.cs:line 41\n   at Squidex.Infrastructure.Commands.GrainCommandMiddleware`2.HandleAsync(CommandContext context, Func`1 next) in /src/src/Squidex.Infrastructure/Commands/GrainCommandMiddleware.cs:line 29\n   at Squidex.Domain.Apps.Entities.Apps.Indexes.AppsByNameIndexCommandMiddleware.HandleAsync(CommandContext context, Func`1 next) in /src/src/Squidex.Domain.Apps.Entities/Apps/Indexes/AppsByNameIndexCommandMiddleware.cs:line 50\n   at Squidex.Domain.Apps.Entities.Apps.Indexes.AppsByNameIndexCommandMiddleware.HandleAsync(CommandContext context, Func`1 next) in /src/src/Squidex.Domain.Apps.Entities/Apps/Indexes/AppsByNameIndexCommandMiddleware.cs:line 66\n   at Squidex.Infrastructure.Commands.GrainCommandMiddleware`2.HandleAsync(CommandContext context, Func`1 next) in /src/src/Squidex.Infrastructure/Commands/GrainCommandMiddleware.cs:line 34\n   at Squidex.Domain.Apps.Entities.Assets.AssetCommandMiddleware.HandleAsync(CommandContext context, Func`1 next) in /src/src/Squidex.Domain.Apps.Entities/Assets/AssetCommandMiddleware.cs:line 102\n   at Squidex.Domain.Apps.Entities.Apps.Invitation.InviteUserCommandMiddleware.HandleAsync(CommandContext context, Func`1 next) in /src/src/Squidex.Domain.Apps.Entities/Apps/Invitation/InviteUserCommandMiddleware.cs:line 47\n   at Squidex.Web.CommandMiddlewares.EnrichWithSchemaIdCommandMiddleware.HandleAsync(CommandContext context, Func`1 next) in /src/src/Squidex.Web/CommandMiddlewares/EnrichWithSchemaIdCommandMiddleware.cs:line 54\n   at Squidex.Web.CommandMiddlewares.ETagCommandMiddleware.HandleAsync(CommandContext context, Func`1 next) in /src/src/Squidex.Web/CommandMiddlewares/ETagCommandMiddleware.cs:line 31\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 244\n   at Squidex.Domain.Apps.Entities.Backup.RestoreGrain.ProcessAsync() in /src/src/Squidex.Domain.Apps.Entities/Backup/RestoreGrain.cs:line 190"
squidex_squidex_1  |   },
squidex_squidex_1  |   "app": {
squidex_squidex_1  |     "name": "Squidex",
squidex_squidex_1  |     "version": "1.0.0.0",
squidex_squidex_1  |     "sessionId": "3dcc509e-ef36-4d98-bab6-354ac8cbc276"
squidex_squidex_1  |   },
squidex_squidex_1  |   "timestamp": "2019-05-03T12:20:04Z"
squidex_squidex_1  | }
squidex_squidex_1  |
squidex_squidex_1  | {
squidex_squidex_1  |   "logLevel": "Information",
squidex_squidex_1  |   "profiler": {
squidex_squidex_1  |     "ExecuteAction": {
squidex_squidex_1  |       "elapsedMsTotal": 0,
squidex_squidex_1  |       "elapsedMsAvg": 0,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     },
squidex_squidex_1  |     "ExecuteResult": {
squidex_squidex_1  |       "elapsedMsTotal": 0,
squidex_squidex_1  |       "elapsedMsAvg": 0,
squidex_squidex_1  |       "count": 1
squidex_squidex_1  |     }
squidex_squidex_1  |   },
squidex_squidex_1  |   "filters": {
squidex_squidex_1  |     "userId": "5c9bdba96ea15a000190a67f",
squidex_squidex_1  |     "clientId": "squidex-frontend",
squidex_squidex_1  |     "costs": 0.0
squidex_squidex_1  |   },
squidex_squidex_1  |   "elapsedRequestMs": 2,
squidex_squidex_1  |   "app": {
squidex_squidex_1  |     "name": "Squidex",
squidex_squidex_1  |     "version": "1.0.0.0",
squidex_squidex_1  |     "sessionId": "3dcc509e-ef36-4d98-bab6-354ac8cbc276"
squidex_squidex_1  |   },
squidex_squidex_1  |   "web": {
squidex_squidex_1  |     "requestId": "c9f4ef60-ed32-4e61-894e-893300c5ba1a",
squidex_squidex_1  |     "requestPath": "/api/apps/restore",
squidex_squidex_1  |     "requestMethod": "GET"
squidex_squidex_1  |   },
squidex_squidex_1  |   "timestamp": "2019-05-03T12:20:04Z"
squidex_squidex_1  | }

spacecat · May 3, 2019, 12:36pm

hmmmm… cleared browser site data in Chrome, stopped and started containers, logged in to Squidex and now the two apps that I was trying to restore earlier appeared on the dashboard…

Will give this another go and report back…

spacecat · May 3, 2019, 12:39pm

lol… worked now

Let me try the second (larger) app… BRB

spacecat · May 3, 2019, 12:43pm

2nd app works too…

however…

now, two schemas from the other app show up, and when I click on them I get a 404. I’ve seen this issue in the past, also when I was doing some backup/restore operations.

spacecat · May 3, 2019, 12:46pm

Restored my 3rd app… and in schemas I now see the schemas for ALL of my apps… seems Squidex is just aggregating them in the UI and not honoring the fact that each schema can only live under one unique app.

spacecat · May 3, 2019, 12:46pm

Note to self: Clear ALL browser site data before restoring an app.

spacecat · May 3, 2019, 12:50pm

@Sebastian is there a way to make those orphaned schemas dissapear?

Sebastian · May 3, 2019, 1:08pm

I don’t see why clearing browser has any effect to the restore operation.

About the orphaned schemas: There is a rebuilder, which runs some stuff depending on options:

github.com

Squidex/squidex/blob/18c45b2fa460940a0820834ee0e431191532cb9a/tools/Migrate_01/RebuildRunner.cs

// ==========================================================================
//  Squidex Headless CMS
// ==========================================================================
//  Copyright (c) Squidex UG (haftungsbeschraenkt)
//  All rights reserved. Licensed under the MIT license.
// ==========================================================================

using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Options;
using Squidex.Infrastructure;

namespace Migrate_01
{
    public sealed class RebuildRunner
    {
        private readonly Rebuilder rebuilder;
        private readonly RebuildOptions rebuildOptions;

        public RebuildRunner(Rebuilder rebuilder, IOptions<RebuildOptions> rebuildOptions)

This file has been truncated. show original

You could extend it to also run this class: https://github.com/Squidex/squidex/blob/18c45b2fa460940a0820834ee0e431191532cb9a/tools/Migrate_01/Migrations/PopulateGrainIndexes.cs

Sebastian · May 3, 2019, 3:32pm

Can you provide me your backup?

spacecat · May 3, 2019, 3:54pm

Sorry, can’t, sensitive data

spacecat · May 3, 2019, 3:54pm

I can help you test though

spacecat · May 3, 2019, 3:57pm

I was looking at your code and my understanding is that we could create a new IMigration with rebuild schemas functionality - so, something along these lines:

using System.Threading.Tasks;
using Squidex.Infrastructure.Migrations;

namespace Migrate_01.Migrations
{
    public sealed class RebuildSchemas : IMigration
    {
        private readonly Rebuilder rebuilder;

        public RebuildSchemas(Rebuilder rebuilder)
        {
            this.rebuilder = rebuilder;
        }

        public Task UpdateAsync()
        {
            return rebuilder.RebuildSchemasAsync();
        }
    }
}

I don’t have any Squidex dev environment setup though so it would probably take me weeks to get something up and running

Sebastian · May 4, 2019, 9:40am

Can you send me an archive with the first 100 events or so only? Perhaps I can reproduce it.

spacecat · May 4, 2019, 11:07am

I actually managed to reproduce it with a new clean copy of Squidex / Mongo containers, new schemas, new everything…

Just restore the two above backup files (I restored animals first and then colors) and you should see duplicate schemas in the colors app.

Sebastian · May 4, 2019, 1:26pm

Thanks a lot for the reproduction. I was able to fix it. The problem was that some data was shared between the restore operations. I have fixed it now.

spacecat · May 4, 2019, 1:51pm

Awesome! Thanks a lot!

Sebastian · May 4, 2019, 2:00pm

Oh, btw I added this setting to fix your indexes: https://github.com/Squidex/squidex/blob/master/src/Squidex/appsettings.json#L437

spacecat · May 4, 2019, 6:21pm

Can you give me a scenario when I could use this setting?

BTW, I restored my apps and all three were restored successfully without any schema dupes!

Sebastian · May 4, 2019, 6:30pm

You asked:

@Sebastian is there a way to make those orphaned schemas dissapear?

Sebastian · May 7, 2019, 4:52pm