Lots of "NewPlacement Request " related errors/warnings in logs

Support
1

Hi @Sebastian,
We are seeing lots of errors in our log file. Can you please take a look? I am not sure why we are seeing these errors.

Note- I have changed IP addresses due to security reasons.

NewPlacement Request S10.53.155.***:11113:397335292*cli/acd5cb90@ea513fb1->S10.53.***.8888:11113:397335292*grn/Squidex.Domain.Apps.Entities.Contents.DomainObject.ContentDomainObjectGrain/0+a16645ee-cdfd-407c-95bb-3d66efe75290--15262@63c32195 InvokeMethodRequest Squidex.Domain.Apps.Entities.Contents.DomainObject.IContentGrain:ExecuteAsync #193061

Response did not arrive on time in 00:00:30 for message: NewPlacement Request S10.53.000.11:11113:397343671*cli/cb3b9abb@f117bc90->S10.53.000.11:11113:397343671*grn/Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain/0+a16645ee-cdfd-407c-95bb-3d66efe75290--450d1fac-1a3f-4dd7-83a3-d949a295fb3a@99e1d08e InvokeMethodRequest Squidex.Domain.Apps.Entities.Schemas.DomainObject.ISchemaGrain:GetStateAsync #87583. Last known status is IsExecuting: True, IsWaiting: False, Diagnostics: [[Activation: S10.53.000.11:11113:397343671*grn/Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain/0+a16645ee-cdfd-407c-95bb-3d66efe75290--450d1fac-1a3f-4dd7-83a3-d949a295fb3a-0x45C28A32@99e1d08e #GrainType=Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain Placement=RandomPlacement State=Valid NonReentrancyQueueSize=0 EnqueuedOnDispatcher=0 InFlightCount=1 NumRunning=1 IdlenessTimeSpan=738371.02:08:43.3939286 CollectionAgeLimit=02:00:00], TaskScheduler status: WorkItemGroup:Name=[Activation: S10.53.000.11:11113:397343671*grn/Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain/0+a16645ee-cdfd-407c-95bb-3d66efe75290--450d1fac-1a3f-4dd7-83a3-d949a295fb3a@99e1d08e #GrainType=Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain Placement=RandomPlacement State=Valid],WorkGroupStatus=Waiting. Currently QueuedWorkItems=0; Total Enqueued=3; Total processed=3; Quantum expirations=0; TaskRunner=ActivationTaskScheduler-63:Queued=0; Detailed context=<[Activation: S10.53.000.11:11113:397343671*grn/Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain/0+a16645ee-cdfd-407c-95bb-3d66efe75290--450d1fac-1a3f-4dd7-83a3-d949a295fb3a-0x45C28A32@99e1d08e #GrainType=Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain Placement=RandomPlacement State=Valid NonReentrancyQueueSize=0 EnqueuedOnDispatcher=0 InFlightCount=1 NumRunning=1 IdlenessTimeSpan=738371.02:08:43.3939718 CollectionAgeLimit=02:00:00 CurrentlyExecuting=NewPlacement Request S10.53.000.11:11113:397343671*cli/cb3b9abb@f117bc90->S10.53.000.11:11113:397343671*grn/Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain/0+a16645ee-cdfd-407c-95bb-3d66efe75290--450d1fac-1a3f-4dd7-83a3-d949a295fb3a@99e1d08e InvokeMethodRequest Squidex.Domain.Apps.Entities.Schemas.DomainObject.ISchemaGrain:GetStateAsync #87583]>, Message NewPlacement Request S10.53.000.11:11113:397343671*cli/cb3b9abb@f117bc90->S10.53.000.11:11113:397343671*grn/Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain/0+a16645ee-cdfd-407c-95bb-3d66efe75290--450d1fac-1a3f-4dd7-83a3-d949a295fb3a@99e1d08e InvokeMethodRequest Squidex.Domain.Apps.Entities.Schemas.DomainObject.ISchemaGrain:GetStateAsync #87583 was enqueued 00:00:28.9663973 ago and has now been executing for 00:00:28.9663559.]. Target History is: <S10.53.000.11:11113:397343671:*grn/Squidex.Domain.Apps.Entities.Schemas.DomainObject.SchemaDomainObjectGrain/0+a16645ee-cdfd-407c-95bb-3d66efe75290--450d1fac-1a3f-4dd7-83a3-d949a295fb3a:@99e1d08e>. About to break its promise.
2

Which version do you use? Please use the template for support requests and format the logs using code blocks.

3

Ok, next time I will use template. I am using 6.7.0

4

It can mean two things:

  1. For some reasons your nodes cannot talk to each other via networking.
  2. The schemas have a bug and the calls never end, like a deadlock.

But with so few context it is hard to say. These logs are hard to resolve, why I moved away from Orleans with 7.0.

I could have a look with a full mongo dump perhaps. But if it does not causes issues I would just ignore it for now.

5

@Sebastian How do I know which schema has a bug? Which kind of bug you are talking about?

6

It should be the schema with ID 450d1fac-1a3f-4dd7-83a3-d949a295fb3a

Squidex uses Orleans, a framework for the virtual actor model: https://dotnet.github.io/orleans/docs/index.html

The log basically says: A content actor requested the information about a schema from an schema actor, but this request took 30 seconds.

I don’t know if there is a bug, but this type of error happens on timeouts and this could be caused by a bug. It could also happen when a call to MongoDB takes very long, like 30 sec instead of 10ms.

7

After looking more logs it seems to be happening for almost all schemas. So bug in schema might be misleading. We will observe more for few more days and let you know.

1 Like