private void job_ExecuteCompleted(object sender, ReportExecutionEventArgs e)
{
#region logging
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: BEGIN ExecuteCompleted", e.Job.Id);
#endregion
try
{
try
{
try
{
if (e.Job.State == ReportExecutionStateEnum.Failed)
{
//only "unexpected" errors should trigger recovery action
if (e.Job.ErrorCode.GetValueOrDefault(ReportExecutionErrorEnum.None) == ReportExecutionErrorEnum.None)
{
Interlocked.Increment(ref _consecutiveFailures);
}
Logger.TraceEvent(
TraceEventType.Error,
0,
"{0}: Report execution {1} failed. {2}.{3}{4}",
this.Name,
e.Job.Id,
e.Job.Error != null ? e.Job.Error.Message : string.Empty,
Environment.NewLine,
e.Job.Error != null ? e.Job.Error.ToString() : string.Empty);
if (_consecutiveFailures > this.MaxConsecutiveFailures)
{
_recoverySleep = true;
}
}
else
{
_consecutiveFailures = 0;
this.CurrentRecoveryInterval = TimeSpan.FromSeconds(5);
_recoverySleep = false;
}
}
finally
{
//complete the execution
Logger.TraceEvent(TraceEventType.Information, 0, "{0}: Completing report execution {1}.", this.Name, e.Job.Id);
ReportExecution.CompleteExecution(e.Job);
}
}
#region exception handling
catch (Exception ex)
{
//TODO: more detailed exception handling
Logger.TraceEvent(TraceEventType.Error, 0, "{0}: {1}", ex.GetType(), ex.Message);
Logger.TraceEvent(TraceEventType.Information, 0, ex.ToString());
_recoverySleep = true;
}
#endregion
}
#region logging
finally
{
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: END ExecuteCompleted", e.Job.Id);
}
#endregion
}
/// <summary>
/// Does the work.
/// </summary>
protected override void DoWork()
{
#region validate configuration
Debug.Assert(this.MaxConcurrentExecutions > 0);
//TODO: validate configuration
#endregion
//use a semaphore to throttle the number of actively processing requests
using (Semaphore semaphore = new Semaphore(MaxConcurrentExecutions, MaxConcurrentExecutions))
{
//need to wait on the semaphore and the wake event
WaitHandle[] waitHandles = new WaitHandle[]
{
semaphore,
base._wakeEvent
};
//start the main loop
while (this.State == WorkerThreadState.Running)
{
try
{
#region recovery
if (_recoverySleep)
{
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: Waiting for recovery interval: {1}", this.Name, this.CurrentRecoveryInterval);
this.Sleep(this.CurrentRecoveryInterval);
_recoverySleep = false;
this.CurrentRecoveryInterval = this.CurrentRecoveryInterval.Add(this.CurrentRecoveryInterval);
if (this.State != WorkerThreadState.Running)
{
return;
}
}
#endregion
#region throttling
//implement throttling to control the number of concurrent work items queued on the Thread Pool
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: Waiting on semaphore.", this.Name);
int eventIndex = WaitHandle.WaitAny(waitHandles);
if (this.State != WorkerThreadState.Running)
{
return;
}
#endregion
//get next report execution
ReportExecution job = null;
try
{
Logger.TraceEvent(TraceEventType.Information, 0, "{0}: Getting next scheduled report execution.", this.Name);
job = ReportExecution.GetNextJob();
}
catch
{
//on error, release semaphore
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: Error getting report execution. Releasing semaphore.", this.Name);
semaphore.Release();
throw;
}
if (job == null)
{
//on no job, release semaphore and go to sleep
Logger.TraceEvent(TraceEventType.Information, 0, "{0}: No queued report executions.", this.Name);
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: Releasing semaphore.", this.Name);
semaphore.Release();
_waitingForPollingInterval = true;
this.Sleep(this.PollingInterval);
_waitingForPollingInterval = false;
}
else
{
//handle message on ThreadPool
ThreadPool.QueueUserWorkItem(state =>
{
#region perform execution
try
{
try
{
#region execute the report
using (AutoResetEvent renderedEvent = new AutoResetEvent(false))
{
job.RenderCompleted += delegate(object sender, ReportExecutionEventArgs e)
{
#region handle render completed event
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: BEGIN RenderCompleted", e.Job.Id);
try
{
if (renderedEvent != null &&
!renderedEvent.SafeWaitHandle.IsClosed &&
!renderedEvent.SafeWaitHandle.IsInvalid)
{
renderedEvent.Set();
}
}
finally
{
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: END RenderCompleted", e.Job.Id);
}
#endregion
};
job.ExecuteCompleted += new EventHandler <ReportExecutionEventArgs>(job_ExecuteCompleted);
//execute the report
Logger.TraceEvent(TraceEventType.Information, 0, "{0}: Processing report execution {1}.", this.Name, job.Id);
//job.Execute(this.ExecutionCredentials, this.ExecutionTimeout);
var format = job.Format;
job.ExecuteAsync(this.ExecutionCredentials, this.ExecutionTimeout, format);
if (!renderedEvent.WaitOne(this.ExecutionTimeout, true))
{
Logger.TraceEvent(TraceEventType.Warning, 0, "{0}: Rendering timed out.", job.Id);
//cancel the execution to ensure that the completed event never fires
job.CancelExecute();
job.Error = new TimeoutException("The operation timed out waiting for rendering");
job.ErrorCode = ReportExecutionErrorEnum.ExecutionTimeout;
job.ErrorCount++;
job.EndTime = DateTime.Now;
job.State = ReportExecutionStateEnum.Failed;
TraceEventType eventType;
switch (job.ErrorCode)
{
case ReportExecutionErrorEnum.InvalidReportParameter:
{
eventType = TraceEventType.Information;
break;
}
default:
{
eventType = TraceEventType.Error;
break;
}
}
Logger.TraceEvent(
eventType,
0,
"{0}: Report execution {1} failed. {2}.{3}{4}",
this.Name,
job.Id,
job.Error != null ? job.Error.Message : string.Empty,
Environment.NewLine,
job.Error != null ? job.Error.ToString() : string.Empty);
//complete the execution
Logger.TraceEvent(TraceEventType.Information, 0, "{0}: Completing report execution {1}.", this.Name, job.Id);
ReportExecution.CompleteExecution(job);
}
//At this point, the report has rendered and is downloading, so we can release
//the semaphore to let another execution through. The ExecuteCompleted event
//will fire when the report has finished downloading.
}
#endregion
}
catch (Exception ex)
{
//TODO: more detailed exception handling
Logger.TraceEvent(TraceEventType.Error, 0, "{0}: {1}", ex.GetType(), ex.Message);
Logger.TraceEvent(TraceEventType.Information, 0, ex.ToString());
_recoverySleep = true;
}
}
finally
{
if (!semaphore.SafeWaitHandle.IsClosed)
{
Logger.TraceEvent(TraceEventType.Verbose, 0, "{0}: Releasing semaphore.", this.Name);
semaphore.Release();
}
//TODO: review the following code. It was indirectly causing a SemaphoreFullException.
////wake-up the dispatcher thread if it is not in "recovery mode"
////this will prevent unnecessary waiting if the next execution time
////of the completed execution is already past
//if (!_recoverySleep && _waitingForPollingInterval)
//{
// this.WakeUp();
//}
}
#endregion
});
}
}
#region exception handling
catch (Exception ex)
{
//TODO: only handle specific exceptions
Logger.TraceEvent(TraceEventType.Error, 0, "{0}: {1}", ex.GetType(), ex.Message);
Logger.TraceEvent(TraceEventType.Information, 0, ex.ToString());
_recoverySleep = true;
}
#endregion
}
}
}
public static void CompleteExecution(ReportExecution execution)
{
#region logging
execution.Log(TraceEventType.Verbose, "BEGIN CompleteExecution()");
#endregion
try
{
int executionId = int.Parse(execution.Id);
if (execution.State != ReportExecutionStateEnum.Failed &&
execution.State != ReportExecutionStateEnum.Succeeded)
{
throw new InvalidOperationException(string.Format("Execution {0} cannot be completed from its current state: {1}", executionId, execution.State));
}
if (execution.State == ReportExecutionStateEnum.Succeeded &&
execution.Data == null)
{
throw new InvalidOperationException(string.Format("Execution {0} is in the 'Succeeded' state but it does not have any data", executionId));
}
using (ReportingDataContext content = new ReportingDataContext("Emdat.InVision.ReportContent"))
using (ReportingDataContext data = new ReportingDataContext())
{
//only update content if the data has been set
if (execution.State == ReportExecutionStateEnum.Succeeded &&
execution.Data != null)
{
#region logging
execution.Log(
TraceEventType.Verbose,
"Setting execution data (fileType={0}, dataLength={1})",
execution.FileType,
execution.Data != null ? execution.Data.Length : 0);
#endregion
try
{
//save the report data
var result = content.SetExecutionData(executionId, execution.FileType, execution.Data);
if (result < 1)
{
throw new ApplicationException(string.Format("The execution data could not be set: {0}", executionId));
}
}
catch (Exception ex)
{
//TFS #13667: retry if there are problems saving the report content
execution.Log(TraceEventType.Warning, "Exception saving report content: {0}", ex.Message);
execution.Log(TraceEventType.Information, "{0}", ex);
execution.Error = ex;
execution.ErrorCount++;
data.SetExecutionRetry(
executionId,
execution.Name,
execution.StartTime,
execution.EndTime,
execution.ErrorDescription,
execution.ErrorCode.HasValue ? (int?)execution.ErrorCode.Value : null,
execution.ErrorCount,
execution.ScheduledRunTime,
"SYSTEM",
DateTime.Now);
return;
}
}
//only fail if success or the error code is set, otherwise, retry
if (execution.State == ReportExecutionStateEnum.Succeeded ||
execution.ErrorCode.HasValue)
{
string nextPrmsXml = ReportParametersHelper.GetParameterValuesXml(execution.NextScheduledRunParameters);
#region logging
execution.Log(
TraceEventType.Verbose,
"Setting execution status (name={0}, startTime={1:s}, endTime={2:s}, state={3}, errorCode={4}, errorCount={5}, usedHistory={6}, nextRun={7:s}, nextPrms={8}, report={9}, subscription={10}, format={11})",
execution.Name,
execution.StartTime,
execution.EndTime,
execution.State,
execution.ErrorCode,
execution.ErrorCount,
!string.IsNullOrEmpty(execution.HistoryId),
execution.NextScheduledRunTime,
nextPrmsXml,
execution.ReportId,
execution.SubscriptionId,
execution.FormatId);
#endregion
//update execution state
data.SetExecutionStatus(
reportExecutionID: executionId,
name: execution.Name,
startDate: execution.StartTime,
endDate: execution.EndTime,
reportExecutionStatusID: (int)execution.State,
errorDescription: execution.ErrorDescription,
errorCount: execution.ErrorCount,
reportExecutionErrorID: execution.ErrorCode.HasValue ? (int?)execution.ErrorCode.Value : null,
usedHistory: !string.IsNullOrEmpty(execution.HistoryId),
nextExecutionDate: execution.NextScheduledRunTime,
nextExecutionParameters: nextPrmsXml,
nextExecutionReportID: execution.ReportId,
nextExecutionSubscriptionID: execution.SubscriptionId,
nextExecutionFormatID: execution.FormatId,
modifiedUser: "******",
modifiedDate: DateTime.Now);
}
else
{
#region logging
execution.Log(
TraceEventType.Verbose,
"Setting execution retry (name={0}, startTime={1:s}, endTime={2:s}, state={3}, errorCode={4}, errorCount={5}, run={6})",
execution.Name,
execution.StartTime,
execution.EndTime,
execution.State,
execution.ErrorCode,
execution.ErrorCount,
execution.ScheduledRunTime);
#endregion
//retry
data.SetExecutionRetry(
executionId,
execution.Name,
execution.StartTime,
execution.EndTime,
execution.ErrorDescription,
execution.ErrorCode.HasValue ? (int?)execution.ErrorCode.Value : null,
execution.ErrorCount,
execution.ScheduledRunTime,
"SYSTEM",
DateTime.Now);
}
}
}
#region logging
finally
{
execution.Log(TraceEventType.Verbose, "END CompleteExecution()");
}
#endregion
}
public static ReportExecution GetNextJob()
{
ReportExecution exec = null;
#region logging
Logger.TraceEvent(
TraceEventType.Verbose,
0,
"{0}: BEGIN GetNextJob()",
System.Threading.Thread.CurrentThread.ManagedThreadId);
#endregion
try
{
using (ReportingDataContext data = new ReportingDataContext())
{
//get the next execution from the queue
var execRow =
(from e in data.GetExecutionFromQueue()
where e.ScheduledStartDate.HasValue
select e).FirstOrDefault();
if (execRow == null)
{
return(null);
}
try
{
var format = data.GetFormat(execRow.ReportFormatID).FirstOrDefault();
var report = data.GetReport(execRow.ReportID, execRow.EnvironmentID).FirstOrDefault();
var subscription = data.GetSubscription(execRow.ReportSubscriptionID).FirstOrDefault();
exec = GetReportExecutionFromRow(execRow, format, report, subscription);
}
catch (Exception ex)
{
//WI #2889: mark the execution for retry on exception
data.SetExecutionRetry(
execRow.ReportExecutionID,
execRow.Name,
null,
null,
ex.ToString(),
null,
execRow.ErrorCount + 1,
execRow.ScheduledStartDate,
"SYSTEM",
DateTime.Now);
//re-throw exception
throw;
}
}
}
#region logging
finally
{
Logger.TraceEvent(
TraceEventType.Verbose,
0,
"{0}: END GetNextJob(id={1}, state={2}, run={3}, nextRun={4}, subscription={5}, reportId={6}, path={7}, formatId={8}, format={9})",
System.Threading.Thread.CurrentThread.ManagedThreadId,
exec != null ? exec.Id : null,
exec != null ? (ReportExecutionStateEnum?)exec.State : null,
exec != null ? exec.ScheduledRunTime : null,
exec != null ? exec.NextScheduledRunTime : null,
exec != null ? exec.SubscriptionId : null,
exec != null ? (int?)exec.ReportId : null,
exec != null ? exec.ReportPath : null,
exec != null ? (int?)exec.FormatId : null,
exec != null ? exec.Format : null);
}
#endregion
return(exec);
}
public ReportExecutionEventArgs(ReportExecution job)
: base()
{
this.Job = job;
}