danielgerlag / danielgerlag/workflow-core

RunnablePoller 'duplicate key' Exceptions when Calling ScheduleCommand

Open
#1,003 0 comments 7 reactions 0 assignees View on GitHub
Dominant language
C#
Stars
5.9k
Forks
1.3k
Avg merge
1d 1h
Merged PRs (30d)
5

Description

There is an issue with ScheduleCommand where we are seeing excessive logging of an exception(see below) regarding UniqueIndex when writing to MongoDB(also when using redis queue provider with mongo persistence)

If possible change the Error to a warning/info as if the item is already written to the scheduled_commands queue surely we don't need to know about a duplicate entry that failed.

Setup:
3 Workers each running WorkflowCore with the following setup
```
services.AddWorkflow(cfg =>
{
cfg.UseMongoDB(options.MongoConnection, options.Prefix);
cfg.UseRedisLocking(redisConnection);
cfg.UseElasticsearch(esConnection.DisableDirectStreaming(disableDirectStreaming), $"{prefix}-wf");
});
```

Here is the Exception Message
```
{
"_id": {
"$oid": "62062fa86620540001558f86"
},
"Timestamp": {
"$date": "2022-02-11T09:43:03.037Z"
},
"Level": "Error",
"MessageTemplate": "A write operation resulted in an error.\n E11000 duplicate key error collection: db.wfc.scheduled_commands index: idx_key dup key: { CommandName: \"ProcessWorkflow\", Data: \"6204fe4837c69d0001d62432\" }",
"RenderedMessage": "A write operation resulted in an error.\n E11000 duplicate key error collection: db.wfc.scheduled_commands index: idx_key dup key: { CommandName: \"ProcessWorkflow\", Data: \"6204fe4837c69d0001d62432\" }",
"Exception": "MongoDB.Driver.MongoWriteException: A write operation resulted in an error.\n E11000 duplicate key error collection: db.wfc.scheduled_commands index: idx_key dup key: { CommandName: \"ProcessWorkflow\", Data: \"6204fe4837c69d0001d62432\" }\n ---> MongoDB.Driver.MongoBulkWriteException`1[WorkflowCore.Models.ScheduledCommand]: A bulk write operation resulted in one or more errors.\n E11000 duplicate key error collection: db.wfc.scheduled_commands index: idx_key dup key: { CommandName: \"ProcessWorkflow\", Data: \"6204fe4837c69d0001d62432\" }\n at MongoDB.Driver.MongoCollectionImpl`1.BulkWriteAsync(IClientSessionHandle session, IEnumerable`1 requests, BulkWriteOptions options, CancellationToken cancellationToken)\n at MongoDB.Driver.MongoCollectionImpl`1.UsingImplicitSessionAsync[TResult](Func`2 funcAsync, CancellationToken cancellationToken)\n at MongoDB.Driver.MongoCollectionBase`1.InsertOneAsync(TDocument document, InsertOneOptions options, Func`3 bulkWriteAsync)\n --- End of inner exception stack trace ---\n at MongoDB.Driver.MongoCollectionBase`1.InsertOneAsync(TDocument document, InsertOneOptions options, Func`3 bulkWriteAsync)\n at WorkflowCore.Persistence.MongoDB.Services.MongoPersistenceProvider.ScheduleCommand(ScheduledCommand command)\n at WorkflowCore.Services.BackgroundTasks.RunnablePoller.PollWorkflows()",
"Properties": {
"SourceContext": "WorkflowCore.Services.BackgroundTasks.RunnablePoller",
"ExceptionDetail": {
"HResult": -2146233088,
"Message": "A write operation resulted in an error.\n E11000 duplicate key error collection: db.wfc.scheduled_commands index: idx_key dup key: { CommandName: \"ProcessWorkflow\", Data: \"6204fe4837c69d0001d62432\" }",
"Source": "MongoDB.Driver",
"InnerException": {
"HResult": -2146233088,
"Message": "A bulk write operation resulted in one or more errors.\n E11000 duplicate key error collection: artemis-wf.wfc.scheduled_commands index: idx_key dup key: { CommandName: \"ProcessWorkflow\", Data: \"6204fe4837c69d0001d62432\" }",
"Source": "MongoDB.Driver",
"Result": {
"DeletedCount": 0,
"InsertedCount": 0,
"IsAcknowledged": true,
"IsModifiedCountAvailable": true,
"MatchedCount": 0,
"ModifiedCount": 0,
"Upserts": [],
"ProcessedRequests": [{
"Document": {
"CommandName": "ProcessWorkflow",
"Data": "6204fe4837c69d0001d62432",
"ExecuteTime": {
"$numberLong": "637801693830185380"
}
},
"ModelType": "InsertOne"
}],
"RequestCount": 1
},
"UnprocessedRequests": [],
"WriteConcernError": null,
"WriteErrors": [{
"Index": 0,
"Category": "DuplicateKey",
"Code": 11000,
"Details": null,
"Message": "E11000 duplicate key error collection: artemis-wf.wfc.scheduled_commands index: idx_key dup key: { CommandName: \"ProcessWorkflow\", Data: \"6204fe4837c69d0001d62432\" }"
}],
"ErrorLabels": [],
"Type": "MongoDB.Driver.MongoBulkWriteException`1[[WorkflowCore.Models.ScheduledCommand, WorkflowCore, Version=3.6.0.0, Culture=neutral, PublicKeyToken=null]]"
},
"WriteConcernError": null,
"WriteError": {
"Index": 0,
"Category": "DuplicateKey",
"Code": 11000,
"Details": null,
"Message": "E11000 duplicate key error collection: db.wfc.scheduled_commands index: idx_key dup key: { CommandName: \"ProcessWorkflow\", Data: \"6204fe4837c69d0001d62432\" }"
},
"ErrorLabels": [],
"Type": "MongoDB.Driver.MongoWriteException"
}
},
"UtcTimestamp": "2022-02-11 09:43:03Z"
}
```

Contributor guide

No contributing guide indexed for this repository

Research direction

Start by tracing MongoPersistenceProvider.ScheduleCommand from the duplicate-key exception and its caller, RunnablePoller.PollWorkflows, using the MongoDB setup described in the issue. Confirm how duplicate scheduled commands are handled, then verify that expected duplicates no longer produce error-level logging while scheduling continues normally.

Written by the indexing model from the issue text.

Assessment

Tech stack
csharp, mongodb, redis
Domain
backend, databases
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.