private async Task StartPoll(
BufferBlock <UnwindedDomainEvent> buffer,
ActionBlock <UnwindedDomainEvent> broadcaster,
String bucketInfo,
List <RebuildProjectionSlotDispatcher> dispatchers,
List <String> allEventTypesHandledByAllSlots,
List <SlotGuaranteedDeliveryBroadcastBlock.SlotInfo <UnwindedDomainEvent> > consumers)
{
if (buffer == null)
{
throw new ArgumentNullException(nameof(buffer));
}
if (broadcaster == null)
{
throw new ArgumentNullException(nameof(broadcaster));
}
if (dispatchers == null)
{
throw new ArgumentNullException(nameof(dispatchers));
}
if (consumers == null)
{
throw new ArgumentNullException(nameof(consumers));
}
if (allEventTypesHandledByAllSlots == null)
{
throw new ArgumentNullException(nameof(allEventTypesHandledByAllSlots));
}
Stopwatch sw = Stopwatch.StartNew();
var eventCollection = _eventUnwinder.UnwindedCollection;
Int64 lastCheckpointTokenDispatched = 0;
Int32 lastSequenceDispatched = 0;
Int64 maxEventDispatched = dispatchers.Max(d => d.LastCheckpointDispatched);
Int64 totalEventToDispatch = eventCollection.Count(Builders <UnwindedDomainEvent> .Filter.Lte(e => e.CheckpointToken, maxEventDispatched));
Int64 dispatchedEvents = 0;
//this is the main cycle that continue to poll events and send to the tpl buffer
Boolean done = false;
while (!done)
{
try
{
IFindFluent <UnwindedDomainEvent, UnwindedDomainEvent> filter = eventCollection
.Find(
//Greater than last dispatched, less than maximum dispatched and one of the events that are elaborated by at least one of the projection
Builders <UnwindedDomainEvent> .Filter.And(
Builders <UnwindedDomainEvent> .Filter.Or( //this is the condition on last dispatched
Builders <UnwindedDomainEvent> .Filter.Gt(e => e.CheckpointToken, lastCheckpointTokenDispatched), //or checkpoint token is greater than last dispatched.
Builders <UnwindedDomainEvent> .Filter.And( //or is equal to the last dispatched, but the EventSequence is greater.
Builders <UnwindedDomainEvent> .Filter.Gt(e => e.EventSequence, lastSequenceDispatched),
Builders <UnwindedDomainEvent> .Filter.Eq(e => e.CheckpointToken, lastCheckpointTokenDispatched)
)
),
Builders <UnwindedDomainEvent> .Filter.Lte(e => e.CheckpointToken, maxEventDispatched) //less than or equal max event dispatched.
, Builders <UnwindedDomainEvent> .Filter.In(e => e.EventType, allEventTypesHandledByAllSlots)
)
);
Logger.InfoFormat($"polled rebuild query {filter}");
var query = filter
.Sort(Builders <UnwindedDomainEvent> .Sort.Ascending(e => e.CheckpointToken).Ascending(e => e.EventSequence));
await query.ForEachAsync(Dispatch).ConfigureAwait(false);
async Task Dispatch(UnwindedDomainEvent eventUnwinded)
{
_pollError = null;
if (Logger.IsDebugEnabled)
{
Logger.DebugFormat("TPL queued event {0}/{1} for bucket {2}", eventUnwinded.CheckpointToken, eventUnwinded.EventSequence, bucketInfo);
}
//rehydrate the event before dispatching
eventUnwinded.EnhanceEvent();
await buffer.SendAsync(eventUnwinded).ConfigureAwait(false);
dispatchedEvents++;
lastSequenceDispatched = eventUnwinded.EventSequence;
lastCheckpointTokenDispatched = eventUnwinded.CheckpointToken;
}
//Send marker unwindws domain event to signal that rebuild is finished
await buffer.SendAsync(UnwindedDomainEvent.LastEvent).ConfigureAwait(false);
done = true;
}
catch (MongoException ex)
{
_pollError = $"Unable to poll event from UnwindedCollection: {ex.Message} - Last good checkpoint dispatched { lastCheckpointTokenDispatched }";
Logger.WarnFormat(ex, "Unable to poll event from UnwindedCollection: {0} - Last good checkpoint dispatched {1}", ex.Message, lastCheckpointTokenDispatched);
}
catch (Exception ex)
{
_pollError = $"Unable to poll event from UnwindedCollection: {ex.Message} - Last good checkpoint dispatched { lastCheckpointTokenDispatched }";
Logger.FatalFormat(ex, "Unable to poll event from UnwindedCollection: {0} - Last good checkpoint dispatched {1}", ex.Message, lastCheckpointTokenDispatched);
throw;
}
}
try
{
Logger.InfoFormat("Finished loading events for bucket {0} wait for tpl to finish flush", bucketInfo);
buffer.Complete();
broadcaster.Completion.Wait(); //wait for all event to be broadcasted.
Task.WaitAll(consumers.Select(c => c.Target.Completion).ToArray()); //wait for all consumers to complete.
Thread.Sleep(1000); //wait for another secondo before finishing.
//create a list of dispatcher to wait for finish, then start waiting.
List <RebuildProjectionSlotDispatcher> dispatcherWaitingToFinish = dispatchers.ToList();
while (dispatcherWaitingToFinish.Count > 0)
{
if (Logger.IsDebugEnabled)
{
Logger.DebugFormat("Waiting for {0} slot to finish events", dispatcherWaitingToFinish.Count);
}
Int32 i = dispatcherWaitingToFinish.Count - 1;
while (i >= 0)
{
var dispatcher = dispatcherWaitingToFinish[i];
if (dispatcher.Finished)
{
foreach (var projection in dispatcher.Projections)
{
try
{
await projection.StopRebuildAsync().ConfigureAwait(false);
}
catch (Exception ex)
{
Logger.ErrorFormat(ex, "Error in StopRebuild for projection {0}", projection.Info.CommonName);
throw;
}
var meter = _metrics.GetMeter(projection.Info.CommonName);
_checkpointTracker.RebuildEnded(projection, meter);
Logger.InfoFormat("Rebuild done for projection {0} @ {1}",
projection.GetType().FullName,
dispatcher.LastCheckpointDispatched
);
}
await _checkpointTracker.UpdateSlotAndSetCheckpointAsync(
dispatcher.SlotName,
dispatcher.Projections.Select(p => p.Info.CommonName),
dispatcher.LastCheckpointDispatched).ConfigureAwait(false);
dispatcherWaitingToFinish.Remove(dispatcher);
Logger.InfoFormat("Rebuild ended for slot {0}", dispatcher.SlotName);
}
i--;
}
if (dispatcherWaitingToFinish.Count > 0)
{
Thread.Sleep(2000);
}
}
sw.Stop();
Logger.InfoFormat("Bucket {0} finished dispathing all events for slots: {1}", bucketInfo, dispatchers.Select(d => d.SlotName).Aggregate((s1, s2) => s1 + ", " + s2));
_status.BucketDone(bucketInfo, dispatchedEvents, sw.ElapsedMilliseconds, totalEventToDispatch);
}
catch (Exception ex)
{
Logger.FatalFormat(ex, "Error during rebuild finish {0}", ex.Message);
throw;
}
}
void DispatchCommit(ICommit commit, string slotName, LongCheckpoint startCheckpoint)
{
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["commit"] = commit.CommitId;
}
if (Logger.IsDebugEnabled)
{
Logger.DebugFormat("Dispatching checkpoit {0} on tenant {1}", commit.CheckpointToken, _config.TenantId);
}
TenantContext.Enter(_config.TenantId);
var chkpoint = LongCheckpoint.Parse(commit.CheckpointToken);
if (chkpoint.LongValue <= startCheckpoint.LongValue)
{
// già fatta
return;
}
var projections = _projectionsBySlot[slotName];
bool dispatchCommit = false;
var eventMessages = commit.Events.ToArray();
var projectionToUpdate = new List <string>();
for (int index = 0; index < eventMessages.Length; index++)
{
var eventMessage = eventMessages[index];
try
{
var evt = (DomainEvent)eventMessage.Body;
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["evType"] = evt.GetType().Name;
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["evMsId"] = evt.MessageId;
}
string eventName = evt.GetType().Name;
foreach (var projection in projections)
{
var cname = projection.GetCommonName();
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["prj"] = cname;
}
var checkpointStatus = _checkpointTracker.GetCheckpointStatus(cname, commit.CheckpointToken);
bool handled;
long ticks = 0;
try
{
var sw = new Stopwatch();
sw.Start();
//if (Logger.IsDebugEnabled)Logger.DebugFormat("Handling {0} with {1}", commit.CheckpointToken, projection.GetType().Name);
handled = projection.Handle(evt, checkpointStatus.IsRebuilding);
//if (Logger.IsDebugEnabled)Logger.DebugFormat("Handled {0} with {1}", commit.CheckpointToken, projection.GetType().Name);
sw.Stop();
ticks = sw.ElapsedTicks;
}
catch (Exception ex)
{
Logger.FatalFormat(ex, "[{3}] Failed checkpoint {0}: {1} > {2}",
commit.CheckpointToken,
commit.StreamId,
eventName,
slotName
);
throw;
}
if (handled)
{
_metrics.Inc(cname, eventName, ticks);
Logger.DebugFormat("[{3}] [{4}] Handled checkpoint {0}: {1} > {2}",
commit.CheckpointToken,
commit.StreamId,
eventName,
slotName,
cname
);
}
if (!checkpointStatus.IsRebuilding)
{
if (handled)
{
dispatchCommit = true;
}
projectionToUpdate.Add(cname);
}
else
{
if (checkpointStatus.IsLast && (index == eventMessages.Length - 1))
{
projection.StopRebuild();
var meter = _metrics.GetMeter(cname);
_checkpointTracker.RebuildEnded(projection, meter);
Logger.InfoFormat("Rebuild done {0} @ {1}",
projection.GetType().FullName,
commit.CheckpointToken
);
}
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["prj"] = null;
}
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["evType"] = null;
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["evMsId"] = null;
}
}
catch (Exception ex)
{
if (Logger.IsDebugEnabled)
{
Logger.ErrorFormat(ex, "{0} -> {1}", eventMessage.Body, ex.Message);
}
throw;
}
}
_checkpointTracker.UpdateSlot(slotName, commit.CheckpointToken);
MetricsHelper.MarkCommitDispatchedCount(slotName, 1);
foreach (var cname in projectionToUpdate)
{
_checkpointTracker.SetCheckpoint(cname, commit.CheckpointToken);
}
if (dispatchCommit)
{
_notifyCommitHandled.SetDispatched(commit);
}
// ok in multithread wihout locks!
if (_maxDispatchedCheckpoint < chkpoint.LongValue)
{
if (Logger.IsDebugEnabled)
{
Logger.DebugFormat("Updating last dispatched checkpoint from {0} to {1}",
_maxDispatchedCheckpoint,
chkpoint.LongValue
);
}
_maxDispatchedCheckpoint = chkpoint.LongValue;
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["commit"] = null;
}
}
private void StartPoll(
BufferBlock <DomainEvent> buffer,
ActionBlock <DomainEvent> broadcaster,
String bucketInfo,
List <RebuildProjectionSlotDispatcher> dispatchers,
List <String> allEventTypesHandledByAllSlots,
List <ActionBlock <DomainEvent> > consumers)
{
Stopwatch sw = Stopwatch.StartNew();
var eventCollection = _eventUnwinder.UnwindedCollection;
Int64 lastCheckpointTokenDispatched = 0;
Int32 lastSequenceDispatched = 0;
Int64 maxEventDispatched = dispatchers.Max(d => d.LastCheckpointDispatched);
Int64 totalEventToDispatch = eventCollection.Count(Builders <UnwindedDomainEvent> .Filter.Lte(e => e.CheckpointToken, maxEventDispatched));
Int64 dispatchedEvents = 0;
//this is the main cycle that continue to poll events and send to the tpl buffer
Boolean done = false;
while (!done)
{
try
{
var query = eventCollection
.Find(
//Greater than last dispatched, less than maximum dispatched and one of the events that are elaborated by at least one of the projection
Builders <UnwindedDomainEvent> .Filter.And(
Builders <UnwindedDomainEvent> .Filter.Or( //this is the condition on last dispatched
Builders <UnwindedDomainEvent> .Filter.Gt(e => e.CheckpointToken, lastCheckpointTokenDispatched), //or checkpoint token is greater than last dispatched.
Builders <UnwindedDomainEvent> .Filter.And( //or is equal to the last dispatched, but the EventSequence is greater.
Builders <UnwindedDomainEvent> .Filter.Gt(e => e.EventSequence, lastSequenceDispatched),
Builders <UnwindedDomainEvent> .Filter.Eq(e => e.CheckpointToken, lastCheckpointTokenDispatched)
)
),
Builders <UnwindedDomainEvent> .Filter.Lte(e => e.CheckpointToken, maxEventDispatched), //less than or equal max event dispatched.
Builders <UnwindedDomainEvent> .Filter.Or( //should be one of the handled type, or the last one.
Builders <UnwindedDomainEvent> .Filter.In(e => e.EventType, allEventTypesHandledByAllSlots),
Builders <UnwindedDomainEvent> .Filter.Eq(e => e.CheckpointToken, maxEventDispatched)
)
)
)
.Sort(Builders <UnwindedDomainEvent> .Sort.Ascending(e => e.CheckpointToken).Ascending(e => e.EventSequence));
foreach (var eventUnwinded in query.ToEnumerable())
{
var evt = eventUnwinded.GetEvent();
if (_logger.IsDebugEnabled)
{
_logger.DebugFormat("TPL queued event {0}/{1} for bucket {2}", eventUnwinded.CheckpointToken, eventUnwinded.EventSequence, bucketInfo);
}
var task = buffer.SendAsync(evt);
//wait till the commit is stored in tpl queue
task.Wait();
dispatchedEvents++;
lastSequenceDispatched = eventUnwinded.EventSequence;
lastCheckpointTokenDispatched = eventUnwinded.CheckpointToken;
}
done = true;
}
catch (MongoException ex)
{
_logger.WarnFormat(ex, "Unable to poll event from UnwindedCollection: {0} - Last good checkpoint dispatched {1}", ex.Message, lastCheckpointTokenDispatched);
}
catch (Exception ex)
{
_logger.FatalFormat(ex, "Unable to poll event from UnwindedCollection: {0} - Last good checkpoint dispatched {1}", ex.Message, lastCheckpointTokenDispatched);
}
}
try
{
_logger.InfoFormat("Finished loading events for bucket {0} wait for tpl to finish flush", bucketInfo);
buffer.Complete();
broadcaster.Completion.Wait(); //wait for all event to be broadcasted.
Task.WaitAll(consumers.Select(c => c.Completion).ToArray()); //wait for all consumers to complete.
Thread.Sleep(1000); //wait for another secondo before finishing.
//create a list of dispatcher to wait for finish
List <RebuildProjectionSlotDispatcher> dispatcherWaitingToFinish = dispatchers.ToList();
while (dispatcherWaitingToFinish.Count > 0)
{
if (_logger.IsDebugEnabled)
{
_logger.DebugFormat("Waiting for {0} slot to finish events", dispatcherWaitingToFinish.Count);
}
Int32 i = dispatcherWaitingToFinish.Count - 1;
while (i >= 0)
{
var dispatcher = dispatcherWaitingToFinish[i];
if (dispatcher.Finished)
{
foreach (var projection in dispatcher.Projections)
{
try
{
projection.StopRebuild();
}
catch (Exception ex)
{
_logger.ErrorFormat(ex, "Error in StopRebuild for projection {0}", projection.GetCommonName());
throw;
}
var meter = _metrics.GetMeter(projection.GetCommonName());
_checkpointTracker.RebuildEnded(projection, meter);
Logger.InfoFormat("Rebuild done for projection {0} @ {1}",
projection.GetType().FullName,
dispatcher.LastCheckpointDispatched
);
}
_checkpointTracker.UpdateSlotAndSetCheckpoint(
dispatcher.SlotName,
dispatcher.Projections.Select(p => p.GetCommonName()),
dispatcher.LastCheckpointDispatched);
dispatcherWaitingToFinish.Remove(dispatcher);
Logger.InfoFormat("Rebuild ended for slot {0}", dispatcher.SlotName);
}
i--;
}
Thread.Sleep(2000);
}
sw.Stop();
_logger.InfoFormat("Bucket {0} finished dispathing all events for slots: {1}", bucketInfo, dispatchers.Select(d => d.SlotName).Aggregate((s1, s2) => s1 + ", " + s2));
_status.BucketDone(bucketInfo, dispatchedEvents, sw.ElapsedMilliseconds, totalEventToDispatch);
}
catch (Exception ex)
{
_logger.FatalFormat(ex, "Error during rebuild finish {0}", ex.Message);
throw;
}
}
void DispatchCommit(ICommit commit, string slotName, Int64 startCheckpoint)
{
Interlocked.Increment(ref _countOfConcurrentDispatchingCommit);
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["commit"] = commit.CommitId;
}
if (Logger.IsDebugEnabled)
{
Logger.DebugFormat("Dispatching checkpoit {0} on tenant {1}", commit.CheckpointToken, _config.TenantId);
}
TenantContext.Enter(_config.TenantId);
var chkpoint = commit.CheckpointToken;
if (!lastCheckpointDispatched.ContainsKey(slotName))
{
lastCheckpointDispatched[slotName] = 0;
}
if (lastCheckpointDispatched[slotName] >= chkpoint)
{
var error = String.Format("Sequence broken, last checkpoint for slot {0} was {1} and now we dispatched {2}",
slotName, lastCheckpointDispatched[slotName], chkpoint);
Logger.Error(error);
throw new ApplicationException(error);
}
if (lastCheckpointDispatched[slotName] + 1 != chkpoint)
{
if (lastCheckpointDispatched[slotName] > 0)
{
Logger.DebugFormat("Sequence of commit non consecutive, last dispatched {0} receiving {1}",
lastCheckpointDispatched[slotName], chkpoint);
}
}
lastCheckpointDispatched[slotName] = chkpoint;
if (chkpoint <= startCheckpoint)
{
//Already dispatched, skip it.
Interlocked.Decrement(ref _countOfConcurrentDispatchingCommit);
return;
}
var projections = _projectionsBySlot[slotName];
bool dispatchCommit = false;
var eventCount = commit.Events.Count;
var projectionToUpdate = new List <string>();
for (int index = 0; index < eventCount; index++)
{
var eventMessage = commit.Events.ElementAt(index);
try
{
var evt = (DomainEvent)eventMessage.Body;
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["evType"] = evt.GetType().Name;
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["evMsId"] = evt.MessageId;
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["evCheckpointToken"] = commit.CheckpointToken;
}
string eventName = evt.GetType().Name;
foreach (var projection in projections)
{
var cname = projection.GetCommonName();
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["prj"] = cname;
}
var checkpointStatus = _checkpointTracker.GetCheckpointStatus(cname, commit.CheckpointToken);
bool handled;
long ticks = 0;
try
{
//pay attention, stopwatch consumes time.
var sw = new Stopwatch();
sw.Start();
handled = projection.Handle(evt, checkpointStatus.IsRebuilding);
sw.Stop();
ticks = sw.ElapsedTicks;
MetricsHelper.IncrementProjectionCounter(cname, slotName, eventName, ticks);
}
catch (Exception ex)
{
var error = String.Format("[Slot: {3} Projection: {4}] Failed checkpoint: {0} StreamId: {1} Event Name: {2}",
commit.CheckpointToken,
commit.StreamId,
eventName,
slotName,
cname);
Logger.Fatal(error, ex);
_engineFatalErrors.Add(error);
throw;
}
if (handled)
{
_metrics.Inc(cname, eventName, ticks);
if (Logger.IsDebugEnabled)
{
Logger.DebugFormat("[{3}] [{4}] Handled checkpoint {0}: {1} > {2}",
commit.CheckpointToken,
commit.StreamId,
eventName,
slotName,
cname
);
}
}
if (!checkpointStatus.IsRebuilding)
{
if (handled)
{
dispatchCommit = true;
}
projectionToUpdate.Add(cname);
}
else
{
if (checkpointStatus.IsLast && (index == eventCount - 1))
{
projection.StopRebuild();
var meter = _metrics.GetMeter(cname);
_checkpointTracker.RebuildEnded(projection, meter);
Logger.InfoFormat("Rebuild done {0} @ {1}",
projection.GetType().FullName,
commit.CheckpointToken
);
}
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["prj"] = null;
}
}
ClearLoggerThreadPropertiesForEventDispatchLoop();
}
catch (Exception ex)
{
Logger.ErrorFormat(ex, "Error dispathing commit id: {0}\nMessage: {1}\nError: {2}",
commit.CheckpointToken, eventMessage.Body, ex.Message);
ClearLoggerThreadPropertiesForEventDispatchLoop();
throw;
}
}
if (projectionToUpdate.Count == 0)
{
//I'm in rebuilding or no projection had run any events, only update slot
_checkpointTracker.UpdateSlot(slotName, commit.CheckpointToken);
}
else
{
//I'm not on rebuilding, we have projection to update, update everything with one call.
_checkpointTracker.UpdateSlotAndSetCheckpoint(slotName, projectionToUpdate, commit.CheckpointToken);
}
MetricsHelper.MarkCommitDispatchedCount(slotName, 1);
if (dispatchCommit)
{
_notifyCommitHandled.SetDispatched(commit);
}
// ok in multithread wihout locks!
if (_maxDispatchedCheckpoint < chkpoint)
{
if (Logger.IsDebugEnabled)
{
Logger.DebugFormat("Updating last dispatched checkpoint from {0} to {1}",
_maxDispatchedCheckpoint,
chkpoint
);
}
_maxDispatchedCheckpoint = chkpoint;
}
if (Logger.IsDebugEnabled)
{
Logger.ThreadProperties["commit"] = null;
}
Interlocked.Decrement(ref _countOfConcurrentDispatchingCommit);
}
