Rules actions not performed

Support
1

I have…

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

what i notice is that this log keep appearing a lot:
2019-10-14T13:33:12.668364575Z {
2019-10-14T13:33:12.669535172Z “logLevel”: “Information”,
2019-10-14T13:33:12.669545672Z “action”: “Migrate”,
2019-10-14T13:33:12.669549772Z “mesage”: “Waiting 500ms to acquire lock.”,
2019-10-14T13:33:12.669553472Z “app”: {
2019-10-14T13:33:12.669568072Z “name”: “Squidex”,
2019-10-14T13:33:12.669571872Z “version”: “3.4.0.0”,
2019-10-14T13:33:12.669575572Z “sessionId”: “c7b0ec2b-b4b9-46ac-83b7-e55300d90b67”
2019-10-14T13:33:12.669579272Z },
2019-10-14T13:33:12.670054871Z “timestamp”: “2019-10-14T13:33:12Z”
2019-10-14T13:33:12.670085271Z }

Don’t know if this is related to the issue

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

First I thought the Rules were not triggered at all. I found out that by default the Consumers were not running. I turned on all consumers, and now the events were captured and enqueued. However, the choosen actions (send email, send slack message) are not performed.

When I look at the database and in the history, all actions are pending with 0 attempts. When I manipulate the date in the database, it will say “Next: in a few minutes”. After the time hit, it will turn into “Next: a few seconds ago”, and that will turn into “Next: a few minutes ago”, etc. etc.

It’s like not attempting nor rescheduling at all, because attempts stays at 0.

Expected behavior

Execute rule action, increase attempt number and on failure reschedule in the future.

Minimal reproduction of the problem

configure rule like this:

{
    "_id": "b6c4c8eb-8ffe-4c92-ba9b-4540f0c170df",
    "Version": {
        "$numberLong": "8"
    },
    "Doc": {
        "appId": "c6f42cad-b033-498c-a715-e8a75e97f9ca,habtic-website",
        "ruleDef": {
            "trigger": {
                "§type": "ContentChangedTriggerV2",
                "schemas": [
                    {
                        "schemaId": "b7cbbbc1-34fb-438b-97ae-7b09210051e9",
                        "condition": "event.type == 'Created'",
                        "isFrozen": true
                    }
                ],
                "handleAll": false,
                "isFrozen": true
            },
            "action": {
                "§type": "SlackAction",
                "webhookUrl": "https://hooks.slack.com/services/REDACTED",
                "text": "Form with the following data submitted\n\nUsername: $CONTENT_DATA.emailaddress.iv\nName: $CONTENT_DATA.name.iv\nBirthdaye: $CONTENT_DATA.birtdate.iv\n",
                "isFrozen": true
            },
            "isEnabled": true
        },
        "isDeleted": false,
        "id": "b6c4c8eb-8ffe-4c92-ba9b-4540f0c170df",
        "createdBy": "subject:5da0879b0409190001bcd74d",
        "lastModifiedBy": "subject:5da0879b0409190001bcd74d",
        "created": "2019-10-14T12:05:13Z",
        "lastModified": "2019-10-14T13:18:06Z",
        "version": {
            "$numberLong": "8"
        }
    }
}

Environment

  • [X] Self hosted with docker (Azure Web App, MongoDB Atlas)
  • [ ] Self hosted with IIS
  • [ ] Self hosted with other version
  • [ ] Cloud version

Version: [VERSION]

Browser:

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

Others:
Triggering ContentChanged with Postman (succeeding)

A record from RuleEvents:

{
    "_id": "0aa10ae2-f6c6-4d99-b3ed-7012b04cf4e4",
    "Created": {
        "$date": {
            "$numberLong": "1571058628750"
        }
    },
    "LastModified": {
        "$date": {
            "$numberLong": "0"
        }
    },
    "AppId": "c6f42cad-b033-498c-a715-e8a75e97f9ca",
    "Result": "Pending",
    "JobResult": "Pending",
    "Job": {
        "jobId": "0aa10ae2-f6c6-4d99-b3ed-7012b04cf4e4",
        "appId": "c6f42cad-b033-498c-a715-e8a75e97f9ca",
        "eventName": "ContactFormCreated",
        "actionName": "SlackAction",
        "actionData": "{\"requestUrl\":\"https://hooks.slack.com/services/REDACTED\",\"requestBody\":\"{\\\"text\\\":\\\"{\\\\\\\"text\\\\\\\": \\\\\\\"Form with the following data submitted\\\\\\\\n\\\\\\\\nUsername: roger.beckers.85@gmail.com\\\\\\\\nName: null\\\\\\\\nBirthdaye: null\\\\\\\"}\\\\n\\\"}\"}",
        "description": "Send message to slack",
        "executionPartition": {
            "$numberLong": "1173187442"
        },
        "created": "2019-10-14T13:10:28Z",
        "expires": "2019-11-13T13:10:28Z"
    },
    "LastDump": null,
    "NumCalls": {
        "$numberInt": "0"
    },
    "Expires": {
        "$date": {
            "$numberLong": "1573650628000"
        }
    },
    "NextAttempt": {
        "$date": {
            "$numberLong": "1571058628750"
        }
    }
}
2

If you go to SQUIDEX_URL/orleans/#/grains you might see a RuleDequeuerGrain. Can you check this?

3

Hi Sebastian,

Thanks for the fast response.
There is no RuleDequeuerGrain, but there is a RuleGrain.

This is the whole list:
EventConsumerGrain
SchemaGrain
AppUISettingsGrain
RuleGrain
AppsByUserIndexGrain
TagGrain
ManagementGrain
EventConsumerManagerGrain
SchemasByAppIndexGrain
AppGrain
SiloGrain
DashboardRemindersGrain
RulesByAppIndexGrain
DashboardGrain
AppsByNameIndexGrain

4

This is strange. Do you see somewhere in your logs a problem with reminders? Reminders are special timers stored in the DB. You could try to delete the Reminders table and run Squidex again.

5

The only application log when restarting is the one waiting for a lock.
After that all is up and running and the Squidex.Orleans_OrleansReminderV2 collection is recreated and empty.

After resetting the consumers, there is 1 document:

{
    "_id": "squidex_GrainReference=0000000000000000000000000000000006ffffff89da8f81+Default_Default",
    "ServiceId": "squidex",
    "GrainId": "GrainReference=0000000000000000000000000000000006ffffff89da8f81+Default",
    "ReminderName": "Default",
    "Etag": "a2b33a48-0900-464a-a8a8-b031f7037e25",
    "Period": "00:10:00",
    "GrainHash": {
        "$numberLong": "201268861"
    },
    "IsDeleted": false,
    "StartAt": {
        "$date": {
            "$numberLong": "1571075492630"
        }
    }
}
6

After digging into the log files I did find some errors about the reminders, this is one of the traces:

2019-10-11T13:07:21.307464205Z Hosting environment: Production
2019-10-11T13:07:21.310255998Z Content root path: /app
2019-10-11T13:07:21.311623595Z Now listening on: http://[::]:80
2019-10-11T13:07:21.312025194Z Application started. Press Ctrl+C to shut down.
2019-10-11T13:07:21.820850165Z {
2019-10-11T13:07:21.820884465Z   "logLevel": "Error",
2019-10-11T13:07:21.820890065Z   "action": "GrainInvoked",
2019-10-11T13:07:21.820893265Z   "status": "Failed",
2019-10-11T13:07:21.820896565Z   "grain": "[LowPrioritySystemTarget: S172.31.200.2:11111:308495107*stg/0/00000000@S00000000]",
2019-10-11T13:07:21.822508861Z   "grainMethod": "System.Threading.Tasks.Task`1[Orleans.Runtime.IGrainReminder] RegisterOrUpdateReminder(Orleans.Runtime.GrainReference, System.String, System.TimeSpan, System.TimeSpan)",
2019-10-11T13:07:21.822521261Z   "exception": {
2019-10-11T13:07:21.822524961Z     "type": "Orleans.Runtime.OrleansException",
2019-10-11T13:07:21.822528661Z     "message": "ReminderService failed initial load of reminders and cannot guarantee that the service will be eventually start without manual intervention or restarting the silo.",
2019-10-11T13:07:21.822532161Z     "stackTrace": "   at Orleans.Runtime.ReminderService.LocalReminderService.DoResponsibilitySanityCheck(GrainReference grainRef, String debugInfo)\n   at Orleans.Runtime.ReminderService.LocalReminderService.RegisterOrUpdateReminder(GrainReference grainRef, String reminderName, TimeSpan dueTime, TimeSpan period)\n   at Orleans.OrleansCodeGenReminderServiceMethodInvoker.Invoke(IAddressable grain, InvokeMethodRequest request)\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.StateFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/StateFilter.cs:line 21\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"
2019-10-11T13:07:21.822537861Z   },
2019-10-11T13:07:21.822540961Z   "app": {
2019-10-11T13:07:21.822543961Z     "name": "Squidex",
2019-10-11T13:07:21.822547061Z     "version": "3.4.0.0",
2019-10-11T13:07:21.824553756Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:21.824564756Z   },
2019-10-11T13:07:21.824568356Z   "timestamp": "2019-10-11T13:07:21Z"
2019-10-11T13:07:21.824571756Z }
2019-10-11T13:07:21.824574756Z 
2019-10-11T13:07:21.890071598Z {
2019-10-11T13:07:21.890132098Z   "logLevel": "Error",
2019-10-11T13:07:21.890146998Z   "action": "GrainInvoked",
2019-10-11T13:07:21.890151898Z   "status": "Failed",
2019-10-11T13:07:21.890156298Z   "grain": "[LowPrioritySystemTarget: S172.31.200.2:11111:308495107*stg/0/00000000@S00000000]",
2019-10-11T13:07:21.891558694Z   "grainMethod": "System.Threading.Tasks.Task`1[Orleans.Runtime.IGrainReminder] RegisterOrUpdateReminder(Orleans.Runtime.GrainReference, System.String, System.TimeSpan, System.TimeSpan)",
2019-10-11T13:07:21.891570194Z   "exception": {
2019-10-11T13:07:21.891573794Z     "type": "System.OperationCanceledException",
2019-10-11T13:07:21.891577194Z     "message": "ReminderService has been stopped.",
2019-10-11T13:07:21.892613792Z     "stackTrace": "   at Orleans.Runtime.ReminderService.LocalReminderService.DoResponsibilitySanityCheck(GrainReference grainRef, String debugInfo)\n   at Orleans.Runtime.ReminderService.LocalReminderService.RegisterOrUpdateReminder(GrainReference grainRef, String reminderName, TimeSpan dueTime, TimeSpan period)\n   at Orleans.OrleansCodeGenReminderServiceMethodInvoker.Invoke(IAddressable grain, InvokeMethodRequest request)\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.StateFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/StateFilter.cs:line 21\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"
2019-10-11T13:07:21.892626092Z   },
2019-10-11T13:07:21.892629392Z   "app": {
2019-10-11T13:07:21.892632492Z     "name": "Squidex",
2019-10-11T13:07:21.892635592Z     "version": "3.4.0.0",
2019-10-11T13:07:21.892638592Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:21.892641792Z   },
2019-10-11T13:07:21.892644692Z   "timestamp": "2019-10-11T13:07:21Z"
2019-10-11T13:07:21.892647792Z }
2019-10-11T13:07:21.892650692Z 
2019-10-11T13:07:21.962590723Z {
2019-10-11T13:07:21.962607123Z   "logLevel": "Error",
2019-10-11T13:07:21.962611423Z   "action": "GrainInvoked",
2019-10-11T13:07:21.962614623Z   "status": "Failed",
2019-10-11T13:07:21.962617723Z   "grain": "[LowPrioritySystemTarget: S172.31.200.2:11111:308495107*stg/0/00000000@S00000000]",
2019-10-11T13:07:21.963877320Z   "grainMethod": "System.Threading.Tasks.Task`1[Orleans.Runtime.IGrainReminder] RegisterOrUpdateReminder(Orleans.Runtime.GrainReference, System.String, System.TimeSpan, System.TimeSpan)",
2019-10-11T13:07:21.963888319Z   "exception": {
2019-10-11T13:07:21.963891819Z     "type": "System.OperationCanceledException",
2019-10-11T13:07:21.963895219Z     "message": "ReminderService has been stopped.",
2019-10-11T13:07:21.963898719Z     "stackTrace": "   at Orleans.Runtime.ReminderService.LocalReminderService.DoResponsibilitySanityCheck(GrainReference grainRef, String debugInfo)\n   at Orleans.Runtime.ReminderService.LocalReminderService.RegisterOrUpdateReminder(GrainReference grainRef, String reminderName, TimeSpan dueTime, TimeSpan period)\n   at Orleans.OrleansCodeGenReminderServiceMethodInvoker.Invoke(IAddressable grain, InvokeMethodRequest request)\n   at Orleans.Runtime.GrainMethodInvoker.Invoke()\n   at Squidex.Infrastructure.Orleans.StateFilter.Invoke(IIncomingGrainCallContext context) in /src/src/Squidex.Infrastructure/Orleans/StateFilter.cs:line 21\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"
2019-10-11T13:07:21.963909619Z   },
2019-10-11T13:07:21.963912819Z   "app": {
2019-10-11T13:07:21.963915819Z     "name": "Squidex",
2019-10-11T13:07:21.963918919Z     "version": "3.4.0.0",
2019-10-11T13:07:21.963921919Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:21.963925019Z   },
2019-10-11T13:07:21.963934519Z   "timestamp": "2019-10-11T13:07:21Z"
2019-10-11T13:07:21.963938519Z }
2019-10-11T13:07:21.963941419Z 
2019-10-11T13:07:22.934645874Z {
2019-10-11T13:07:22.934674874Z   "logLevel": "Error",
2019-10-11T13:07:22.934681074Z   "message": "SelectTarget failed with Grain directory is stopping",
2019-10-11T13:07:22.934685974Z   "eventId": {
2019-10-11T13:07:22.934690274Z     "id": 100071
2019-10-11T13:07:22.934694374Z   },
2019-10-11T13:07:22.934698574Z   "exception": {
2019-10-11T13:07:22.934702874Z     "type": "System.InvalidOperationException",
2019-10-11T13:07:22.934707274Z     "message": "Grain directory is stopping",
2019-10-11T13:07:22.937972866Z     "stackTrace": "   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.CheckIfShouldForward(GrainId grainId, Int32 hopCount, String operationDescription)\n   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.LookupAsync(GrainId grainId, Int32 hopCount)\n   at Orleans.Runtime.Scheduler.AsyncClosureWorkItem`1.Execute()\n   at Orleans.Runtime.Placement.RandomPlacementDirector.OnSelectActivation(PlacementStrategy strategy, GrainId target, IPlacementRuntime context)\n   at Orleans.Runtime.Placement.PlacementDirectorsManager.SelectOrAddActivation(ActivationAddress sendingAddress, PlacementTarget targetGrain, IPlacementRuntime context, PlacementStrategy strategy)\n   at Orleans.Runtime.Dispatcher.AddressMessageAsync(Message message, PlacementTarget target, PlacementStrategy strategy, ActivationAddress targetAddress)\n   at Orleans.Runtime.Dispatcher.<>c__DisplayClass37_0.<<AsyncSendMessage>b__1>d.MoveNext()"
2019-10-11T13:07:22.938006566Z   },
2019-10-11T13:07:22.938027966Z   "app": {
2019-10-11T13:07:22.938031666Z     "name": "Squidex",
2019-10-11T13:07:22.938035366Z     "version": "3.4.0.0",
2019-10-11T13:07:22.939355863Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:22.939366163Z   },
2019-10-11T13:07:22.939369763Z   "timestamp": "2019-10-11T13:07:22Z",
2019-10-11T13:07:22.939400063Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:22.939403763Z }
2019-10-11T13:07:22.939406963Z 
2019-10-11T13:07:22.940573160Z {
2019-10-11T13:07:22.940643060Z   "logLevel": "Warning",
2019-10-11T13:07:22.940649960Z   "message": "Discarding OneWay rejection for message OneWay S172.31.200.2:11111:308495107*cli/7b8345ac@6c58b28c->*grn/68072C12/00000000+172.31.200.2:11111@308495107 #442: . Exc = Grain directory is stopping",
2019-10-11T13:07:22.940655060Z   "eventId": {
2019-10-11T13:07:22.941625758Z     "id": 101002
2019-10-11T13:07:22.941647558Z   },
2019-10-11T13:07:22.941652357Z   "app": {
2019-10-11T13:07:22.941656457Z     "name": "Squidex",
2019-10-11T13:07:22.941660657Z     "version": "3.4.0.0",
2019-10-11T13:07:22.941664857Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:22.941669257Z   },
2019-10-11T13:07:22.941673257Z   "timestamp": "2019-10-11T13:07:22Z",
2019-10-11T13:07:22.941677557Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:22.941681857Z }
2019-10-11T13:07:22.941685757Z 
2019-10-11T13:07:23.931402966Z {
2019-10-11T13:07:23.931431666Z   "logLevel": "Error",
2019-10-11T13:07:23.931445666Z   "message": "SelectTarget failed with Grain directory is stopping",
2019-10-11T13:07:23.931449966Z   "eventId": {
2019-10-11T13:07:23.931453366Z     "id": 100071
2019-10-11T13:07:23.931456766Z   },
2019-10-11T13:07:23.931459966Z   "exception": {
2019-10-11T13:07:23.931463366Z     "type": "System.InvalidOperationException",
2019-10-11T13:07:23.931466966Z     "message": "Grain directory is stopping",
2019-10-11T13:07:23.933556461Z     "stackTrace": "   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.CheckIfShouldForward(GrainId grainId, Int32 hopCount, String operationDescription)\n   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.LookupAsync(GrainId grainId, Int32 hopCount)\n   at Orleans.Runtime.Scheduler.AsyncClosureWorkItem`1.Execute()\n   at Orleans.Runtime.Placement.RandomPlacementDirector.OnSelectActivation(PlacementStrategy strategy, GrainId target, IPlacementRuntime context)\n   at Orleans.Runtime.Placement.PlacementDirectorsManager.SelectOrAddActivation(ActivationAddress sendingAddress, PlacementTarget targetGrain, IPlacementRuntime context, PlacementStrategy strategy)\n   at Orleans.Runtime.Dispatcher.AddressMessageAsync(Message message, PlacementTarget target, PlacementStrategy strategy, ActivationAddress targetAddress)\n   at Orleans.Runtime.Dispatcher.<>c__DisplayClass37_0.<<AsyncSendMessage>b__1>d.MoveNext()"
2019-10-11T13:07:23.933571361Z   },
2019-10-11T13:07:23.933575061Z   "app": {
2019-10-11T13:07:23.933578161Z     "name": "Squidex",
2019-10-11T13:07:23.933581461Z     "version": "3.4.0.0",
2019-10-11T13:07:23.935039058Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:23.935050458Z   },
2019-10-11T13:07:23.935053958Z   "timestamp": "2019-10-11T13:07:23Z",
2019-10-11T13:07:23.935057458Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:23.935060658Z }
2019-10-11T13:07:23.935063658Z 
2019-10-11T13:07:23.937017953Z {
2019-10-11T13:07:23.937030453Z   "logLevel": "Warning",
2019-10-11T13:07:23.937034553Z   "message": "Discarding OneWay rejection for message OneWay S172.31.200.2:11111:308495107*cli/7b8345ac@6c58b28c->*grn/68072C12/00000000+172.31.200.2:11111@308495107 #443: . Exc = Grain directory is stopping",
2019-10-11T13:07:23.937038453Z   "eventId": {
2019-10-11T13:07:23.938022850Z     "id": 101002
2019-10-11T13:07:23.938033850Z   },
2019-10-11T13:07:23.938037350Z   "app": {
2019-10-11T13:07:23.938040650Z     "name": "Squidex",
2019-10-11T13:07:23.938043950Z     "version": "3.4.0.0",
2019-10-11T13:07:23.938047250Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:23.938050750Z   },
2019-10-11T13:07:23.938053850Z   "timestamp": "2019-10-11T13:07:23Z",
2019-10-11T13:07:23.938057250Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:23.938060650Z }
2019-10-11T13:07:23.938063650Z 

2019-10-11T13:07:24.962736075Z {
2019-10-11T13:07:24.962842375Z   "logLevel": "Error",
2019-10-11T13:07:24.962903375Z   "message": "SelectTarget failed with Grain directory is stopping",
2019-10-11T13:07:24.962921275Z   "eventId": {
2019-10-11T13:07:24.962953574Z     "id": 100071
2019-10-11T13:07:24.962983574Z   },
2019-10-11T13:07:24.963007974Z   "exception": {
2019-10-11T13:07:24.963019974Z     "type": "System.InvalidOperationException",
2019-10-11T13:07:24.963051574Z     "message": "Grain directory is stopping",
2019-10-11T13:07:24.963065374Z     "stackTrace": "   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.CheckIfShouldForward(GrainId grainId, Int32 hopCount, String operationDescription)\n   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.LookupAsync(GrainId grainId, Int32 hopCount)\n   at Orleans.Runtime.Scheduler.AsyncClosureWorkItem`1.Execute()\n   at Orleans.Runtime.Placement.RandomPlacementDirector.OnSelectActivation(PlacementStrategy strategy, GrainId target, IPlacementRuntime context)\n   at Orleans.Runtime.Placement.PlacementDirectorsManager.SelectOrAddActivation(ActivationAddress sendingAddress, PlacementTarget targetGrain, IPlacementRuntime context, PlacementStrategy strategy)\n   at Orleans.Runtime.Dispatcher.AddressMessageAsync(Message message, PlacementTarget target, PlacementStrategy strategy, ActivationAddress targetAddress)\n   at Orleans.Runtime.Dispatcher.<>c__DisplayClass37_0.<<AsyncSendMessage>b__1>d.MoveNext()"
2019-10-11T13:07:24.963126974Z   },
2019-10-11T13:07:24.963140774Z   "app": {
2019-10-11T13:07:24.963165074Z     "name": "Squidex",
2019-10-11T13:07:24.963177074Z     "version": "3.4.0.0",
2019-10-11T13:07:24.963199974Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:24.963211974Z   },
2019-10-11T13:07:24.963235474Z   "timestamp": "2019-10-11T13:07:24Z",
2019-10-11T13:07:24.963247474Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:24.963273674Z }
2019-10-11T13:07:24.963286174Z 
2019-10-11T13:07:24.963312274Z {
2019-10-11T13:07:24.963324774Z   "logLevel": "Warning",
2019-10-11T13:07:24.963348973Z   "message": "Discarding OneWay rejection for message OneWay S172.31.200.2:11111:308495107*cli/7b8345ac@6c58b28c->*grn/68072C12/00000000+172.31.200.2:11111@308495107 #444: . Exc = Grain directory is stopping",
2019-10-11T13:07:24.963361973Z   "eventId": {
2019-10-11T13:07:24.963391073Z     "id": 101002
2019-10-11T13:07:24.963403473Z   },
2019-10-11T13:07:24.963426473Z   "app": {
2019-10-11T13:07:24.963438073Z     "name": "Squidex",
2019-10-11T13:07:24.963463873Z     "version": "3.4.0.0",
2019-10-11T13:07:24.963476473Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:24.963785772Z   },
2019-10-11T13:07:24.963818472Z   "timestamp": "2019-10-11T13:07:24Z",
2019-10-11T13:07:24.963859772Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:24.963876372Z }
2019-10-11T13:07:24.963905472Z 
2019-10-11T13:07:25.931858834Z {
2019-10-11T13:07:25.931886634Z   "logLevel": "Error",
2019-10-11T13:07:25.932803231Z   "message": "SelectTarget failed with Grain directory is stopping",
2019-10-11T13:07:25.932809231Z   "eventId": {
2019-10-11T13:07:25.932813531Z     "id": 100071
2019-10-11T13:07:25.932817831Z   },
2019-10-11T13:07:25.932822031Z   "exception": {
2019-10-11T13:07:25.932826331Z     "type": "System.InvalidOperationException",
2019-10-11T13:07:25.932831031Z     "message": "Grain directory is stopping",
2019-10-11T13:07:25.939786215Z     "stackTrace": "   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.CheckIfShouldForward(GrainId grainId, Int32 hopCount, String operationDescription)\n   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.LookupAsync(GrainId grainId, Int32 hopCount)\n   at Orleans.Runtime.Scheduler.AsyncClosureWorkItem`1.Execute()\n   at Orleans.Runtime.Placement.RandomPlacementDirector.OnSelectActivation(PlacementStrategy strategy, GrainId target, IPlacementRuntime context)\n   at Orleans.Runtime.Placement.PlacementDirectorsManager.SelectOrAddActivation(ActivationAddress sendingAddress, PlacementTarget targetGrain, IPlacementRuntime context, PlacementStrategy strategy)\n   at Orleans.Runtime.Dispatcher.AddressMessageAsync(Message message, PlacementTarget target, PlacementStrategy strategy, ActivationAddress targetAddress)\n   at Orleans.Runtime.Dispatcher.<>c__DisplayClass37_0.<<AsyncSendMessage>b__1>d.MoveNext()"
2019-10-11T13:07:25.939823214Z   },
2019-10-11T13:07:25.939829214Z   "app": {
2019-10-11T13:07:25.939833614Z     "name": "Squidex",
2019-10-11T13:07:25.939838014Z     "version": "3.4.0.0",
2019-10-11T13:07:25.945174802Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:25.945187101Z   },
2019-10-11T13:07:25.945190901Z   "timestamp": "2019-10-11T13:07:25Z",
2019-10-11T13:07:25.945207201Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:25.945210701Z }
2019-10-11T13:07:25.945213801Z 
2019-10-11T13:07:25.961069363Z {
2019-10-11T13:07:25.961082863Z   "logLevel": "Warning",
2019-10-11T13:07:25.961087263Z   "message": "Discarding OneWay rejection for message OneWay S172.31.200.2:11111:308495107*cli/7b8345ac@6c58b28c->*grn/68072C12/00000000+172.31.200.2:11111@308495107 #445: . Exc = Grain directory is stopping",
2019-10-11T13:07:25.961091563Z   "eventId": {
2019-10-11T13:07:25.962260160Z     "id": 101002
2019-10-11T13:07:25.962271460Z   },
2019-10-11T13:07:25.962275360Z   "app": {
2019-10-11T13:07:25.962278760Z     "name": "Squidex",
2019-10-11T13:07:25.962282160Z     "version": "3.4.0.0",
2019-10-11T13:07:25.962285660Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:25.962289260Z   },
2019-10-11T13:07:25.962292460Z   "timestamp": "2019-10-11T13:07:25Z",
2019-10-11T13:07:25.962296160Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:25.962299560Z }
2019-10-11T13:07:25.962302660Z 
2019-10-11T13:07:26.338996250Z {
2019-10-11T13:07:26.339349449Z   "logLevel": "Warning",
2019-10-11T13:07:26.339358449Z   "message": "Ignoring System.OperationCanceledException exception thrown from an action called by Silo.Stop.",
2019-10-11T13:07:26.339362349Z   "eventId": {
2019-10-11T13:07:26.339365449Z     "id": 100325
2019-10-11T13:07:26.339368549Z   },
2019-10-11T13:07:26.339371649Z   "exception": {
2019-10-11T13:07:26.339374849Z     "type": "System.OperationCanceledException",
2019-10-11T13:07:26.339516149Z     "message": "The operation was canceled.",
2019-10-11T13:07:26.339524749Z     "stackTrace": "   at System.Threading.CancellationToken.ThrowOperationCanceledException()\n   at System.Threading.ManualResetEventSlim.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)\n   at System.Threading.Tasks.Task.SpinThenBlockingWait(Int32 millisecondsTimeout, CancellationToken cancellationToken)\n   at System.Threading.Tasks.Task.InternalWaitCore(Int32 millisecondsTimeout, CancellationToken cancellationToken)\n   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)\n   at Orleans.Runtime.Silo.<>c__DisplayClass84_0.<OnBecomeActiveStop>b__1()\n   at Orleans.Runtime.Utils.SafeExecute(Action action, ILogger logger, Func`1 callerGetter)"
2019-10-11T13:07:26.339536949Z   },
2019-10-11T13:07:26.339540149Z   "app": {
2019-10-11T13:07:26.339543149Z     "name": "Squidex",
2019-10-11T13:07:26.339546149Z     "version": "3.4.0.0",
2019-10-11T13:07:26.339549149Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:26.339552349Z   },
2019-10-11T13:07:26.339555149Z   "timestamp": "2019-10-11T13:07:26Z",
2019-10-11T13:07:26.339558249Z   "category": "Orleans.Runtime.Silo"
2019-10-11T13:07:26.339561249Z }
2019-10-11T13:07:26.339564149Z 
2019-10-11T13:07:26.930503021Z {
2019-10-11T13:07:26.930524221Z   "logLevel": "Error",
2019-10-11T13:07:26.930528621Z   "message": "SelectTarget failed with Grain directory is stopping",
2019-10-11T13:07:26.930532121Z   "eventId": {
2019-10-11T13:07:26.930535221Z     "id": 100071
2019-10-11T13:07:26.930538321Z   },
2019-10-11T13:07:26.930541521Z   "exception": {
2019-10-11T13:07:26.930552821Z     "type": "System.InvalidOperationException",
2019-10-11T13:07:26.930556221Z     "message": "Grain directory is stopping",
2019-10-11T13:07:26.933235414Z     "stackTrace": "   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.CheckIfShouldForward(GrainId grainId, Int32 hopCount, String operationDescription)\n   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.LookupAsync(GrainId grainId, Int32 hopCount)\n   at Orleans.Runtime.Scheduler.AsyncClosureWorkItem`1.Execute()\n   at Orleans.Runtime.Placement.RandomPlacementDirector.OnSelectActivation(PlacementStrategy strategy, GrainId target, IPlacementRuntime context)\n   at Orleans.Runtime.Placement.PlacementDirectorsManager.SelectOrAddActivation(ActivationAddress sendingAddress, PlacementTarget targetGrain, IPlacementRuntime context, PlacementStrategy strategy)\n   at Orleans.Runtime.Dispatcher.AddressMessageAsync(Message message, PlacementTarget target, PlacementStrategy strategy, ActivationAddress targetAddress)\n   at Orleans.Runtime.Dispatcher.<>c__DisplayClass37_0.<<AsyncSendMessage>b__1>d.MoveNext()"
2019-10-11T13:07:26.933257914Z   },
2019-10-11T13:07:26.933261614Z   "app": {
2019-10-11T13:07:26.933265014Z     "name": "Squidex",
2019-10-11T13:07:26.933268514Z     "version": "3.4.0.0",
2019-10-11T13:07:26.934531811Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:26.934541811Z   },
2019-10-11T13:07:26.934545211Z   "timestamp": "2019-10-11T13:07:26Z",
2019-10-11T13:07:26.934548411Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:26.934558111Z }
2019-10-11T13:07:26.934561211Z 
2019-10-11T13:07:26.935730808Z {
2019-10-11T13:07:26.935744408Z   "logLevel": "Warning",
2019-10-11T13:07:26.935749508Z   "message": "Discarding OneWay rejection for message OneWay S172.31.200.2:11111:308495107*cli/7b8345ac@6c58b28c->*grn/68072C12/00000000+172.31.200.2:11111@308495107 #446: . Exc = Grain directory is stopping",
2019-10-11T13:07:26.935754408Z   "eventId": {
2019-10-11T13:07:26.936468107Z     "id": 101002
2019-10-11T13:07:26.936477607Z   },
2019-10-11T13:07:26.936481007Z   "app": {
2019-10-11T13:07:26.936484007Z     "name": "Squidex",
2019-10-11T13:07:26.936487007Z     "version": "3.4.0.0",
2019-10-11T13:07:26.936496307Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:26.936499907Z   },
2019-10-11T13:07:26.936502807Z   "timestamp": "2019-10-11T13:07:26Z",
2019-10-11T13:07:26.936505907Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:26.936509006Z }
2019-10-11T13:07:26.936511906Z 
2019-10-11T13:07:27.931399003Z {
2019-10-11T13:07:27.931420403Z   "logLevel": "Error",
2019-10-11T13:07:27.931425203Z   "message": "SelectTarget failed with Grain directory is stopping",
2019-10-11T13:07:27.931429103Z   "eventId": {
2019-10-11T13:07:27.931432403Z     "id": 100071
2019-10-11T13:07:27.931435903Z   },
2019-10-11T13:07:27.931447303Z   "exception": {
2019-10-11T13:07:27.931451203Z     "type": "System.InvalidOperationException",
2019-10-11T13:07:27.931454703Z     "message": "Grain directory is stopping",
2019-10-11T13:07:27.933863897Z     "stackTrace": "   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.CheckIfShouldForward(GrainId grainId, Int32 hopCount, String operationDescription)\n   at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.LookupAsync(GrainId grainId, Int32 hopCount)\n   at Orleans.Runtime.Scheduler.AsyncClosureWorkItem`1.Execute()\n   at Orleans.Runtime.Placement.RandomPlacementDirector.OnSelectActivation(PlacementStrategy strategy, GrainId target, IPlacementRuntime context)\n   at Orleans.Runtime.Placement.PlacementDirectorsManager.SelectOrAddActivation(ActivationAddress sendingAddress, PlacementTarget targetGrain, IPlacementRuntime context, PlacementStrategy strategy)\n   at Orleans.Runtime.Dispatcher.AddressMessageAsync(Message message, PlacementTarget target, PlacementStrategy strategy, ActivationAddress targetAddress)\n   at Orleans.Runtime.Dispatcher.<>c__DisplayClass37_0.<<AsyncSendMessage>b__1>d.MoveNext()"
2019-10-11T13:07:27.933881797Z   },
2019-10-11T13:07:27.933886997Z   "app": {
2019-10-11T13:07:27.933899697Z     "name": "Squidex",
2019-10-11T13:07:27.933904097Z     "version": "3.4.0.0",
2019-10-11T13:07:27.935137794Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:27.935158294Z   },
2019-10-11T13:07:27.935162794Z   "timestamp": "2019-10-11T13:07:27Z",
2019-10-11T13:07:27.935166494Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:27.935230594Z }
2019-10-11T13:07:27.935235894Z 
2019-10-11T13:07:27.937862187Z {
2019-10-11T13:07:27.937877287Z   "logLevel": "Warning",
2019-10-11T13:07:27.937882387Z   "message": "Discarding OneWay rejection for message OneWay S172.31.200.2:11111:308495107*cli/7b8345ac@6c58b28c->*grn/68072C12/00000000+172.31.200.2:11111@308495107 #447: . Exc = Grain directory is stopping",
2019-10-11T13:07:27.937994287Z   "eventId": {
2019-10-11T13:07:27.938823285Z     "id": 101002
2019-10-11T13:07:27.938844885Z   },
2019-10-11T13:07:27.938850085Z   "app": {
2019-10-11T13:07:27.938854285Z     "name": "Squidex",
2019-10-11T13:07:27.938858485Z     "version": "3.4.0.0",
2019-10-11T13:07:27.938862785Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:27.938867285Z   },
2019-10-11T13:07:27.938871285Z   "timestamp": "2019-10-11T13:07:27Z",
2019-10-11T13:07:27.938875485Z   "category": "Orleans.Runtime.Dispatcher"
2019-10-11T13:07:27.938879885Z }
2019-10-11T13:07:27.938889485Z 
2019-10-11T13:07:28.343187908Z {
2019-10-11T13:07:28.343238208Z   "logLevel": "Warning",
2019-10-11T13:07:28.343243608Z   "message": "Lifecycle stop operations canceled by request.",
2019-10-11T13:07:28.343247308Z   "app": {
2019-10-11T13:07:28.343250308Z     "name": "Squidex",
2019-10-11T13:07:28.343254408Z     "version": "3.4.0.0",
2019-10-11T13:07:28.343283508Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:28.343287108Z   },
2019-10-11T13:07:28.343290308Z   "timestamp": "2019-10-11T13:07:28Z",
2019-10-11T13:07:28.345099503Z   "category": "Orleans.Runtime.SiloLifecycleSubject"
2019-10-11T13:07:28.345111703Z }
2019-10-11T13:07:28.345115303Z 
2019-10-11T13:07:28.411061444Z {
2019-10-11T13:07:28.411076044Z   "logLevel": "Error",
2019-10-11T13:07:28.411080444Z   "message": "RunClientMessagePump has thrown exception",
2019-10-11T13:07:28.411083944Z   "eventId": {
2019-10-11T13:07:28.411086944Z     "id": 100326
2019-10-11T13:07:28.411090044Z   },
2019-10-11T13:07:28.411093144Z   "exception": {
2019-10-11T13:07:28.411096544Z     "type": "System.OperationCanceledException",
2019-10-11T13:07:28.411100044Z     "message": "The operation was canceled.",
2019-10-11T13:07:28.413343238Z     "stackTrace": "   at System.Collections.Concurrent.BlockingCollection`1.TryTakeWithNoTimeValidation(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken, CancellationTokenSource combinedTokenSource)\n   at System.Collections.Concurrent.BlockingCollection`1.TryTake(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken)\n   at System.Collections.Concurrent.BlockingCollection`1.Take(CancellationToken cancellationToken)\n   at Orleans.Runtime.HostedClient.RunClientMessagePump()"
2019-10-11T13:07:28.413374638Z   },
2019-10-11T13:07:28.413385338Z   "app": {
2019-10-11T13:07:28.413388438Z     "name": "Squidex",
2019-10-11T13:07:28.413391538Z     "version": "3.4.0.0",
2019-10-11T13:07:28.413394538Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:28.413397638Z   },
2019-10-11T13:07:28.413400738Z   "timestamp": "2019-10-11T13:07:28Z",
2019-10-11T13:07:28.413403738Z   "category": "Orleans.Runtime.HostedClient"
2019-10-11T13:07:28.413406938Z }
2019-10-11T13:07:28.413409838Z 

2019-10-11T13:07:33.371527058Z {
2019-10-11T13:07:33.371563458Z   "logLevel": "Warning",
2019-10-11T13:07:33.371568858Z   "message": "Failed to update status to dead in the alotted time during shutdown",
2019-10-11T13:07:33.371572858Z   "app": {
2019-10-11T13:07:33.371576358Z     "name": "Squidex",
2019-10-11T13:07:33.371580058Z     "version": "3.4.0.0",
2019-10-11T13:07:33.371583658Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:33.371587358Z   },
2019-10-11T13:07:33.372171657Z   "timestamp": "2019-10-11T13:07:33Z",
2019-10-11T13:07:33.372183257Z   "category": "Orleans.Runtime.MembershipService.MembershipTableManager"
2019-10-11T13:07:33.372188457Z }
2019-10-11T13:07:33.372192557Z 
2019-10-11T13:07:33.380639336Z {
2019-10-11T13:07:33.380655436Z   "logLevel": "Warning",
2019-10-11T13:07:33.380660536Z   "message": "Thread System.Threading.Thread is exiting work loop due to cancellation token. WorkItemGroup: System*WorkItemGroup:Name=*stg/20/00000014,WorkGroupStatus=Running, Have 0 work items in the queue.",
2019-10-11T13:07:33.380664836Z   "eventId": {
2019-10-11T13:07:33.381709434Z     "id": 101222
2019-10-11T13:07:33.381722034Z   },
2019-10-11T13:07:33.381726034Z   "thread": "System.Threading.Thread",
2019-10-11T13:07:33.381729734Z   "workItemGroup": "System*WorkItemGroup:Name=*stg/20/00000014,WorkGroupStatus=Running",
2019-10-11T13:07:33.381733634Z   "workItemCount": "0",
2019-10-11T13:07:33.381737234Z   "app": {
2019-10-11T13:07:33.381740634Z     "name": "Squidex",
2019-10-11T13:07:33.381744134Z     "version": "3.4.0.0",
2019-10-11T13:07:33.381755934Z     "sessionId": "74a5928d-f894-4426-907c-73a75b0c91aa"
2019-10-11T13:07:33.381768334Z   },
2019-10-11T13:07:33.381772434Z   "timestamp": "2019-10-11T13:07:33Z",
2019-10-11T13:07:33.381776034Z   "category": "Orleans.Runtime.Scheduler *stg/20/00000014.WorkItemGroup"
2019-10-11T13:07:33.381779634Z }
2019-10-11T13:07:33.381782934Z 
2019-10-11T13:07:33.394252003Z Application is shutting down...
7

Stopping Orleans is a little bit bumpy, so everything that is related to stopping can usually be ignored. But this one is interesting:

ReminderService failed initial load of reminders and cannot guarantee that the service will be eventually start without manual intervention or restarting the silo.

8

Ow, and what I do notice, is that this error happened on the first day I started working with it. I did have some issues logging in at the beginning. I expect that it was because the password requirements were not met for the admin account. Could this be the cause during first boot?

And is it normal that the logs are flooded with information logs “Waiting 500ms to acquire lock.”?
It’s really hard to analyse the logs because of this.

9

Could you restart squidex and then send me the full logs before you make any HTTP calls?

You can send me a file via PM.

10

Are you running in clustering mode with more than 1 node? If the answer is yes, then he lock message is normal. It means that one node is waiting for the other node to complete the migration.

If the answer is no, then something went totally wrong and your are stuck in migration somehow.

Can you check the Migration collection?

You should see something like:

{ 
    "_id" : "Default", 
    "IsLocked" : false, 
    "Version" : NumberInt(19)
}
11

Squidex is running in a single instance, Mongo is running in a 3 node cluster.
The migration collection shows:

{
    "_id": "Default",
    "IsLocked": true,
    "Version": {
        "$numberInt": "0"
    }
}

It’s not running in production yet. So maybe I better shut it down for the night and start it up in the morning. Like that it’s easier to check which logs are from booting up freshly.

Might it be a good idea that I make a backup with the builtin function, nuke the database, reboot and then restore? And if so, what do I need to think of that is not backed up?

12

I would just clear Reminders and the Migration collection. I wonder how you can pass the lock. It should stop you from running the API.

13

After deleting reminders and migration, suddenly i got a lot of emails and slack messages sent.
Seems that fixed it, but I got now a lot of 502 errors and some logs that the container is unhealthy and restarting.

I’ll let it rest till tomorrow, thanks a lot for your fast help!

14

I am here to help tomorrow :slight_smile:

15

Hi Sebastian,

I couldn’t get the container stable anymore, but since the migration folder was not locked but still on version 0, I assumed that the migrations didn’t go well 100% afterall. Maybe there is a chance that putting a non valid password in the appsettings caused this. Because it’s not yet a production environment, I decided to nuke the db and restart te container: Now all is working perfectly! :slight_smile:

I do have another concern tho, I hope you don’t mind asking it in this thread.
The automatic resizing and caching of images looks like a nice feature but also a risky one. Is there any protection against bots that would try to attack this by, for example, scripting to fetch the image with width=1 to width=1000000 for every image? Because that would be really bad for the azure storage account.

16

No, there is no protection. I would put cloudfront or so in front of it. Or azure API proxy with rate limits?

Btw: Great that you solved it, but I am still a little bit worried about it. But because ASP.NET Core 3.0 has changed a few things of the startup phase I will wait until the migration is complete.

17

Yeah I will look into Azure solutions for that than.
After upgrading to 3.0, maybe you can try to reproduce it by setting up an incorrect password.
The moment we move to a production environment, I will try to reproduce it also and let you know if I can.

1 Like