public static void ClearMarkCommandExecution(this ILoggerThreadContextManager loggerThreadContextManager) { loggerThreadContextManager.ClearContextProperty(LoggingConstants.CommandId); loggerThreadContextManager.ClearContextProperty(LoggingConstants.UserId); loggerThreadContextManager.ClearContextProperty(LoggingConstants.CommandDescription); //correlation id during command execution is given by a special context data and default to message id if correlation is not present loggerThreadContextManager.ClearContextProperty(LoggingConstants.CorrleationId); }
private async Task DispatchCommitAsync(IChunk chunk, string slotName, Int64 startCheckpoint) { Interlocked.Increment(ref _countOfConcurrentDispatchingCommit); _loggerThreadContextManager.SetContextProperty("commit", $"{chunk.OperationId}/{chunk.Position}"); if (_logger.IsDebugEnabled) { _logger.DebugFormat("Dispatching checkpoit {0} on tenant {1}", chunk.Position, _config.TenantId); } TenantContext.Enter(_config.TenantId); var chkpoint = chunk.Position; 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 JarvisFrameworkEngineException(error); } if (lastCheckpointDispatched[slotName] + 1 != chkpoint && lastCheckpointDispatched[slotName] > 0) { _logger.DebugFormat("Sequence of commit not consecutive (probably holes), 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]; object[] events = GetArrayOfObjectFromChunk(chunk); var eventCount = events.Length; //now it is time to dispatch the commit, we will dispatch each projection //and for each projection we dispatch all the events present in changeset bool someProjectionProcessedTheEvent = false; foreach (var projection in projections) { var cname = projection.Info.CommonName; Object eventMessage = null; try { //Foreach projection we need to dispach every event for (int index = 0; index < eventCount; index++) { eventMessage = events[index]; var message = eventMessage as IMessage; string eventName = eventMessage.GetType().Name; _loggerThreadContextManager.SetContextProperty("evType", eventName); _loggerThreadContextManager.SetContextProperty("evMsId", message?.MessageId); _loggerThreadContextManager.SetContextProperty("evCheckpointToken", chunk.Position); _loggerThreadContextManager.SetContextProperty("prj", cname); var checkpointStatus = _checkpointTracker.GetCheckpointStatus(cname, chunk.Position); long ticks = 0; try { //pay attention, stopwatch consumes time. var sw = new Stopwatch(); sw.Start(); var eventProcessed = await projection .HandleAsync(eventMessage, checkpointStatus.IsRebuilding) .ConfigureAwait(false); someProjectionProcessedTheEvent |= eventProcessed; sw.Stop(); ticks = sw.ElapsedTicks; KernelMetricsHelper.IncrementProjectionCounter(cname, slotName, eventName, ticks, sw.ElapsedMilliseconds); if (_logger.IsDebugEnabled) { _logger.DebugFormat("[Slot:{3}] [Projection {4}] Handled checkpoint {0}: {1} > {2}", chunk.Position, chunk.PartitionId, $"eventName: {eventName} [event N°{index}]", slotName, cname ); } } catch (Exception ex) { var error = String.Format("[Slot: {3} Projection: {4}] Failed checkpoint: {0} StreamId: {1} Event Name: {2}", chunk.Position, chunk.PartitionId, eventName, slotName, cname); _logger.Fatal(error, ex); _engineFatalErrors.Add(String.Format("{0}\n{1}", error, ex)); throw; } } //End of event cycle } catch (Exception ex) { _loggerThreadContextManager.ClearContextProperty("commit"); _logger.ErrorFormat(ex, "Error dispathing Chunk [{0}]\n Message: {1}\n Error: {2}\n", chunk.Position, eventMessage?.GetType()?.Name, ex.Message); throw; } finally { _loggerThreadContextManager.ClearContextProperty("evType"); _loggerThreadContextManager.ClearContextProperty("evMsId"); _loggerThreadContextManager.ClearContextProperty("evCheckpointToken"); _loggerThreadContextManager.ClearContextProperty("prj"); } projection.CheckpointProjected(chunk.Position); //TODO: Evaluate if it is needed to update single projection checkpoint //Update this projection, set all events of this checkpoint as dispatched. //await _checkpointTracker.UpdateProjectionCheckpointAsync(cname, chunk.Position).ConfigureAwait(false); } //End of projection cycle. await _checkpointTracker.UpdateSlotAndSetCheckpointAsync( slotName, projections.Select(_ => _.Info.CommonName), chunk.Position, someEventDispatched : someProjectionProcessedTheEvent).ConfigureAwait(false); KernelMetricsHelper.MarkCommitDispatchedCount(slotName, 1); await _notifyCommitHandled.SetDispatched(slotName, chunk).ConfigureAwait(false); // 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; } _loggerThreadContextManager.ClearContextProperty("commit"); Interlocked.Decrement(ref _countOfConcurrentDispatchingCommit); }