public void CycleFinished(RFWorkQueueItem i, RFProcessingResult result)
{
if (i.ProcessingKey != null && _requests.ContainsKey(i.ProcessingKey) && i.Item is RFProcessInstruction)
{
_requests[i.ProcessingKey].CycleFinished((i.Item as RFProcessInstruction).ToString(), result);
}
}
private void ProcessInstructionThread(RFWorkQueueItem i)
{
try
{
// To make transaction work we'd have to use a single SQL connection to do all reads and writes
/* using (var ts = new TransactionScope(TransactionScopeOption.Required, new TransactionOptions
* {
* IsolationLevel = System.Transactions.IsolationLevel.ReadCommitted,
* Timeout = TimeSpan.FromSeconds(30)
* }))*/
{
Log.Debug(this, "Started thread to process instruction {0}", i.Item as RFProcessInstruction);
var sink = new RFBufferingSink(); // create thread-local manager to buffer events and instructions, then send them back in bulk
RFProcessingResult result = null;
try
{
result = _context.Engine.Process(i.Item as RFInstruction, _context.GetProcessingContext(i.ProcessingKey, sink, sink, null));
}
catch (Exception ex)
{
Log.Exception(this, ex, "Exception Thread processing queue item ", i);
result = RFProcessingResult.Error(new string[] { ex.Message }, ex is DbException || ex is TimeoutException);
}
// send result and all buffered events/instructions to external event manager (since
// we can't guarantee delivery order with MSMQ)
_eventSink.RaiseEvent(this, new RFProcessingFinishedEvent(i, result, sink.GetItems()), i.ProcessingKey);
//ts.Complete();
}
}
catch (Exception ex)
{
Log.Exception(this, ex, "Exception Thread processing queue item ", i);
}
}
public RFProcessingResult Process(RFInstruction i, IRFProcessingContext processingContext)
{
try
{
if (i is RFProcessInstruction)
{
var pi = i as RFProcessInstruction;
if (_processes.ContainsKey(pi.ProcessName))
{
var process = _processes[pi.ProcessName];
return(ProcessInstruction(process, i as RFProcessInstruction, processingContext));
}
else
{
var msg = String.Format("Process {0} referenced by instruction {1} not found in engine configuration.", pi.ProcessName, i);
Log.Error(this, msg);
return(RFProcessingResult.Error(new string[] { msg }, false));
}
}
}
catch (Exception ex)
{
Log.Exception(this, ex, "Exception processing instruction {0}", i);
return(RFProcessingResult.Error(new string[] { ex.Message }, false));
}
return(new RFProcessingResult());
}
public RFProcessingFinishedEvent(RFWorkQueueItem item, RFProcessingResult result, RFWorkQueueItem[] queueItems)
{
Item = item;
Timestamp = DateTime.Now;
Result = result;
WorkQueueItems = queueItems;
}
public void CycleFinished(string processName, RFProcessingResult result)
{
lock (mSync)
{
FinishedCycles++;
ProcessingCycles--;
var singleMessage = result.Messages?.FirstOrDefault();
if (result.IsError)
{
LogError(singleMessage ?? "Unknown error");
LogMessage(processName, "ERROR: " + singleMessage ?? String.Empty);
}
else if (result.UpdatedKeys != null && result.UpdatedKeys.Count > 0)
{
LogMessage(processName, singleMessage ?? string.Format("OK ({0} update{1})", result.UpdatedKeys.Count, result.UpdatedKeys.Count == 1 ? "" : "s"));
}
else if (result.WorkDone)
{
LogMessage(processName, singleMessage ?? "OK");
}
// otherwise don't bother to output name - no updates
if (result.UpdatedKeys != null)
{
foreach (var k in result.UpdatedKeys)
{
LogKey(k);
}
}
}
}
public override RFProcessingResult Process()
{
var interval = InstanceParams.Interval;
var result = new RFProcessingResult();
foreach (var configFunc in mConfigFunc)
{
var config = configFunc(Context);
if (config.ShouldTrigger(interval))
{
var key = config.TriggerKey;
if (config.GraphInstance != null)
{
key = key.CreateForInstance(config.GraphInstance(interval));
Context.SaveEntry(RFDocument.Create(key, new RFGraphProcessorTrigger {
TriggerStatus = true, TriggerTime = interval.IntervalEnd
}));
}
else
{
Context.SaveEntry(RFDocument.Create(key, new RFScheduleTrigger {
LastTriggerTime = interval.IntervalEnd
}));
}
result.WorkDone = true;
}
}
return(result);
}
public void Finished(RFWorkQueueItem i, RFProcessingResult result)
{
if (Filter(i))
{
Update(i.Item, GetState(result), null, result);
}
}
private void ProcessInstructionThread(RFWorkQueueItem i)
{
try
{
Log.Debug(this, "Started thread to process instruction {0}", i.Item as RFProcessInstruction);
var result = _context.Engine.Process(i.Item as RFInstruction, _context.GetProcessingContext(i.ProcessingKey, _instructionSink, _eventSink, this));
_eventSink.RaiseEvent(this, new RFProcessingFinishedEvent(i, result, null), i.ProcessingKey); // we do not store work queue items in-proc
}
catch (Exception ex)
{
Log.Exception(this, ex, "Exception Thread processing queue item ", i);
_eventSink.RaiseEvent(this, new RFProcessingFinishedEvent(i, RFProcessingResult.Error(new string[] { ex.Message }, false), null), i.ProcessingKey);
}
}
private static DispatchState GetState(RFProcessingResult result)
{
if (result.IsError)
{
return(DispatchState.Error);
}
else if (!result.WorkDone && (result.UpdatedKeys == null || result.UpdatedKeys.Count == 0))
{
return(DispatchState.Skipped);
}
else
{
return(DispatchState.Finished);
}
}
protected void UpdateResult(RFGraphProcessorStatus status, RFProcessingResult result)
{
if (status != null && result != null)
{
if (status.CalculationOK)
{
var date = InstanceParams != null && GraphInstance.ValueDate.HasValue ? GraphInstance.ValueDate.Value.ToString() : "n/a";
if (!result.WorkDone)
{
Context.SystemLog.Info(this, "Run process {0} but no outputs have changed.", String.Format("{0} [{1}]", ProcessName, date));
}
}
else
{
var date = InstanceParams != null && GraphInstance.ValueDate.HasValue ? GraphInstance.ValueDate.Value.ToString() : "n/a";
result.AddMessage(status.Message);
result.IsError = true;
}
}
}
public void ProcessingFinished(RFWorkQueueItem i, RFProcessingResult result)
{
Monitor.Enter(_sync);
if (i.Item is RFProcessInstruction)
{
_inProgress.Remove(i);//.Item as RFProcessInstruction);
RFStatic.Log.Debug(typeof(RFGraphDispatchQueue), "Processing finished for {0} ({1} in progress)", i.Item, _inProgress.Count);
_dispatchStore.Finished(i, result);
}
RefreshReadyQueue();
RefreshInstructionCount();
if (!InProgress(i.ProcessingKey))
{
QueueItem(new RFWorkQueueItem {
Item = new RFRequestCompleted(), ProcessingKey = i.ProcessingKey
}); // notify monitor this request is done
}
Monitor.PulseAll(_sync); // inprogress finished and nothing left
Monitor.Exit(_sync);
}
public override RFProcessingResult Process()
{
var result = new RFProcessingResult();
var processor = Config.Processor();
processor.Initialize(Context);
if (!processor.HasInstance(GraphInstance))
{
// do not process if not existent
Context.SystemLog.Debug(this, "Not running graph process {0} as flagged no instance for {1}", ProcessName, InstanceParams.ToString());
return(result);
}
var missingInputs = new SortedSet <string>();
var dsw = Stopwatch.StartNew();
var domain = LoadDomain(processor, Context, ref missingInputs);
var domainLoadTime = dsw.ElapsedMilliseconds;
long domainSaveTime = 0;
var pd = Stopwatch.StartNew();
try
{
if (domain != null)
{
result.WorkDone = processor.ProcessDomain(domain);
result.AddMessages(new SortedSet <string>(processor.Log.GetErrors()));
var processingTime = pd.ElapsedMilliseconds;
if (processor.ProcessorStatus.CalculationOK)
{
var sd = Stopwatch.StartNew();
result.UpdatedKeys = SaveDomain(domain, Context);
result.WorkDone |= result.UpdatedKeys.Count > 0;
domainSaveTime = sd.ElapsedMilliseconds;
}
else // soft error - RFLogicException in processing (incorrect file, config etc.)
{
Context.SystemLog.Error(this, processor.ProcessorStatus.Message);
Context.UserLog.LogEntry(new RFUserLogEntry
{
Action = "Warning",
IsWarning = true,
Description = String.Format("Calculation error: {0}", processor.ProcessorStatus.Message),
IsUserAction = false,
Processor = Config.Name,
Username = "******",
Area = null,
ValueDate = GraphInstance.ValueDate ?? RFDate.NullDate
});
}
var md = Stopwatch.StartNew();
UpdateResult(processor.ProcessorStatus, result);
LogGraphStat(processor.ProcessorStatus);
var miscTime = md.ElapsedMilliseconds;
Context.SystemLog.Debug(this, "## Graph Process {0}: {1} ms total = {2} (load) + {3} (process) + {4} (save) + {5} (misc)",
this.ProcessName,
domainLoadTime + processingTime + domainSaveTime + miscTime,
domainLoadTime, processingTime, domainSaveTime, miscTime);
SetProcessEntry(new RFProcessEntry
{
IOTime = domainLoadTime + domainSaveTime + miscTime,
ProcessingTime = processingTime,
Success = processor.ProcessorStatus.CalculationOK,
Message = processor.ProcessorStatus.Message,
ProcessName = Config.Name,
GraphName = Config.GraphName,
GraphInstance = GraphInstance,
NumUpdates = result.UpdatedKeys?.Count ?? 0
});
}
else
{
/* don't spam these messages any more
* domain = processor.CreateDomain();
* domain.SetError("Not yet available: {0}", String.Join(",", missingInputs));
* LogStatus(domain, false);
* SaveDomain(domain, processor, Context);*/
Context.SystemLog.Info(this, "Not running graph process {0} as unable to construct full domain.", Config.Name);
//LogGraphStat(domain);
}
}
catch (Exception ex) // serious (system) error like database disconnection, NULL etc
{
processor.ProcessorStatus.SetError(ex.Message);
//UpdateResult(processor.ProcessorStatus, result);
//Log.Error(this, "Exception running graph process {0}: {1}", Config.Name, ex.Message);
LogGraphStat(processor.ProcessorStatus);
SetProcessEntry(new RFProcessEntry
{
IOTime = domainLoadTime,
ProcessingTime = pd.ElapsedMilliseconds,
Success = false,
Message = ex.Message,
ProcessName = Config.Name,
GraphName = Config.GraphName,
GraphInstance = GraphInstance,
NumUpdates = 0
});
throw; // report exception higher up
}
return(result);
}
protected RFProcessingResult ProcessInstruction(RFEngineProcess process, RFProcessInstruction i, IRFProcessingContext processingContext)
{
var result = new RFProcessingResult();
try
{
var sw = Stopwatch.StartNew();
var startTime = DateTimeOffset.Now;
bool completed = false;
try
{
var processorInstance = process.CreateInstance();
if (processorInstance != null)
{
if (_config.MaxRuntime.Ticks > 0)
{
var maxRuntime = TimeSpan.FromTicks(Math.Max(processorInstance.MaxRuntime().Ticks, _config.MaxRuntime.Ticks));
var timerTask = Task.Delay(maxRuntime).ContinueWith(t =>
{
if (!completed)
{
try
{
processorInstance.Cancel();
}
catch (Exception ex)
{
Log.Warning(this, "Exception cancelling process {0}: {1}", process.Name, ex.Message);
}
throw new TimeoutException(String.Format("Cancelling process {0} as it's taken too long (max runtime = {1} seconds).", process.Name, maxRuntime.TotalSeconds));
}
});
}
result = process.RunInstance(processorInstance, i, processingContext);
}
}
catch (Exception ex) // hard exception, or softs should have bene handled by now
{
var message = ex.InnerException?.Message ?? ex.Message;
result.AddMessage(message);
result.IsError = true;
result.ShouldRetry |= (ex is DbException || ex is TimeoutException || ex is RFTransientSystemException || ex?.InnerException is DbException || ex?.InnerException is TimeoutException);
Log.Exception(this, ex, "Exception running process {0}", process.Name);
/*processingContext.UserLog.LogEntry(new RFUserLogEntry
* {
* Action = "Error",
* Area = null,
* Description = String.Format("Error running process {0}: {1}", process.Name, message),
* IsUserAction = false,
* IsWarning = true,
* Processor = process.Name
* });*/
}
completed = true;
LogProcessingStat(process, i, sw, startTime);
Log.Debug(this, String.Format("Engine: process {0} process took {1} ms.", process.Name, sw.ElapsedMilliseconds));
}
catch (Exception ex) // a really bad system exception
{
Log.Exception(this, ex, "Exception processing instruction {0} by process {1}", i, process);
result.AddMessage(ex.Message);
result.IsError = true;
result.ShouldRetry |= (ex is DbException || ex is TimeoutException || ex is RFTransientSystemException || ex?.InnerException is DbException || ex?.InnerException is TimeoutException);
}
return(result);
}
public RFProcessingResult RunInstance(IRFEngineProcessor processorInstance, RFInstruction instruction, IRFProcessingContext context)
{
var pi = instruction as RFProcessInstruction;
if (pi != null)
{
var sw = Stopwatch.StartNew();
RFEngineProcessorParam instanceParams = null;
try
{
instanceParams = Config.InstanceParams(instruction);
processorInstance.Initialize(instanceParams, context, KeyDomain, Config.Name);
var result = processorInstance.Process();
result.AddMessages(processorInstance.Log.GetErrors());
if ((result.WorkDone || result.IsError) && !(processorInstance is RFSchedulerProcessor))
{
context.SystemLog.LogProcess(this, processorInstance.GetProcessEntry() ?? new RFProcessEntry
{
GraphInstance = (instanceParams as RFEngineProcessorGraphInstanceParam)?.Instance,
GraphName = (processorInstance as RFGraphProcess)?.GraphName,
IOTime = 0,
ProcessingTime = sw.ElapsedMilliseconds,
Message = String.Join("\r\n", result.Messages),
ProcessName = Config.Name,
Success = !result.IsError,
NumUpdates = 1
});
context.SystemLog.Info(this, "Run process {0}{1} in {2}ms", Config.Name, instanceParams != null ? String.Format(" ({0})", instanceParams) : String.Empty, sw.ElapsedMilliseconds);
}
return(result);
}
catch (RFLogicException ex) // soft exception (incorrect file etc.)
{
context.UserLog.LogEntry(new RFUserLogEntry
{
Action = "Warning",
IsWarning = true,
Description = String.Format("Calculation error: {0}", ex.Message),
IsUserAction = false,
Processor = Config.Name,
Username = "******",
Area = null,
ValueDate = RFDate.NullDate
});
context.SystemLog.Warning(this, "Logic Exception on process {0}: {1}", Config.Name, ex.Message);
context.SystemLog.LogProcess(this, processorInstance.GetProcessEntry() ?? new RFProcessEntry
{
GraphInstance = (instanceParams as RFEngineProcessorGraphInstanceParam)?.Instance,
GraphName = (processorInstance as RFGraphProcess)?.GraphName,
IOTime = 0,
ProcessingTime = sw.ElapsedMilliseconds,
Message = ex.Message,
ProcessName = Config.Name,
Success = false,
NumUpdates = 0
});
var result = new RFProcessingResult
{
IsError = true,
Messages = new SortedSet <string>(processorInstance?.Log?.GetErrors() ?? new string[0]),
WorkDone = false,
ShouldRetry = false,
UpdatedKeys = new System.Collections.Generic.List <RFCatalogKey>()
};
result.AddMessage(ex.Message);
return(result);
}
catch (Exception ex) // hard exception - system, null etc.
{
context.SystemLog.LogProcess(this, processorInstance?.GetProcessEntry() ?? new RFProcessEntry
{
GraphInstance = (instanceParams as RFEngineProcessorGraphInstanceParam)?.Instance,
GraphName = (processorInstance as RFGraphProcess)?.GraphName,
IOTime = 0,
ProcessingTime = sw.ElapsedMilliseconds,
Message = ex.Message,
ProcessName = Config.Name,
Success = false,
NumUpdates = 0
});
throw;
}
}
throw new RFSystemException(this, "Cannot process empty instruction");
}
private void Update(string dispatchKey, string processName, string instanceName, RFDate?valueDate, DispatchState state, long?weight, RFProcessingResult result, RFInstruction instruction)
{
try
{
using (var conn = new SqlConnection(_context.SystemConfig.DocumentStoreConnectionString))
{
conn.Open();
using (var cmd = new SqlCommand("RIFF.UpdateDispatchQueue", conn))
{
cmd.CommandType = System.Data.CommandType.StoredProcedure;
cmd.Parameters.AddWithValue("@Environment", RFStringHelpers.StringToSQL(_context.SystemConfig.Environment, false, 10, false));
cmd.Parameters.AddWithValue("@ItemType", (int)ItemType.GraphProcessInstruction);
cmd.Parameters.AddWithValue("@DispatchKey", RFStringHelpers.StringToSQL(dispatchKey, false, 140, false));
cmd.Parameters.AddWithValue("@ProcessName", RFStringHelpers.StringToSQL(processName, true, 100, false));
cmd.Parameters.AddWithValue("@GraphInstance", RFStringHelpers.StringToSQL(instanceName, true, 20, false));
if (valueDate != null && valueDate.Value.IsValid())
{
cmd.Parameters.AddWithValue("@ValueDate", valueDate.Value.Date);
}
else
{
cmd.Parameters.AddWithValue("@ValueDate", DBNull.Value);
}
if (weight.HasValue)
{
cmd.Parameters.AddWithValue("@Weight", weight.Value);
}
else
{
cmd.Parameters.AddWithValue("@Weight", DBNull.Value);
}
cmd.Parameters.AddWithValue("@DispatchState", (int)state);
if (state == DispatchState.Started)
{
cmd.Parameters.AddWithValue("@LastStart", DateTimeOffset.Now);
}
else
{
cmd.Parameters.AddWithValue("@LastStart", DBNull.Value);
}
if (result?.Messages != null)
{
cmd.Parameters.AddWithValue("@Message", RFStringHelpers.StringToSQL(String.Join("|", result.Messages), true, 200, false));
}
else if (state == DispatchState.Finished || state == DispatchState.Skipped || state == DispatchState.Started)
{
cmd.Parameters.AddWithValue("@Message", String.Empty); // clear past error messages
}
else
{
cmd.Parameters.AddWithValue("@Message", DBNull.Value);
}
if (result != null)
{
cmd.Parameters.AddWithValue("@ShouldRetry", result.ShouldRetry);
}
else
{
cmd.Parameters.AddWithValue("@ShouldRetry", false);
}
if (state == DispatchState.Queued && instruction != null)
{
cmd.Parameters.AddWithValue("@InstructionType", RFStringHelpers.StringToSQL(instruction.GetType().FullName, false, 200, false));
cmd.Parameters.AddWithValue("@InstructionContent", RFXMLSerializer.SerializeContract(instruction));
}
else
{
cmd.Parameters.AddWithValue("@InstructionType", DBNull.Value);
cmd.Parameters.AddWithValue("@InstructionContent", DBNull.Value);
}
cmd.ExecuteNonQuery();
}
}
}
catch (Exception ex)
{
_context.Log.Exception(this, "Error updating Dispatch Store", ex);
}
}
private void Update(IRFWorkQueueableItem i, DispatchState state, long?weight, RFProcessingResult result)
{
var processName = (i as RFProcessInstruction)?.ProcessName;
var instanceName = (i as RFGraphProcessInstruction)?.Instance?.Name;
var instanceDate = (i as RFGraphProcessInstruction)?.Instance?.ValueDate;
Update(i.DispatchKey(), processName, instanceName, instanceDate, state, weight, result, i as RFInstruction);
}
private void ProcessingFinished(RFWorkQueueItem i, RFProcessingResult result)
{
_requestTracker.CycleFinished(i, result);
_dispatchQueue.ProcessingFinished(i, result);
}
