public void ProcessJobs_ShallRetryUpTo3Times()
{
var countDownEvent = new CountdownEvent(3);
_jobStore.Setup(p => p.Add(It.IsAny <InferenceJob>(), It.IsAny <bool>()))
.Callback(() =>
{
countDownEvent.Signal();
})
.Throws(new System.Exception());
_configuration.AeTitle = _aeTitle;
_configuration.ProcessorSettings.Add("timeout", "1");
_configuration.ProcessorSettings.Add("jobRetryDelay", "100");
_configuration.ProcessorSettings.Add("pipeline-first", "PIPELINE1");
var processor = new AeTitleJobProcessor(_configuration, _notificationService, _loggerFactory.Object, _jobStore.Object, _cleanupQueue.Object, _dicomToolkit.Object, _cancellationTokenSource.Token);
_notificationService.NewInstanceStored(_instances.First());
Assert.True(countDownEvent.Wait(10000));
_jobStore.Verify(p => p.Add(It.IsAny <InferenceJob>(), false), Times.Exactly(3));
_logger.VerifyLogging($"Failed to submit job, will retry later: PatientId={_instances.First().PatientId}, Study={_instances.First().StudyInstanceUid}", LogLevel.Information, Times.AtLeast(1));
_logger.VerifyLogging($"Failed to submit job after 3 retries: PatientId={_instances.First().PatientId}, Study={_instances.First().StudyInstanceUid}", LogLevel.Error, Times.Once());
}
public void ProcessJobs_ShallStopUponCancellationRequest()
{
_configuration.AeTitle = _aeTitle;
_configuration.ProcessorSettings.Add("timeout", "1");
_configuration.ProcessorSettings.Add("pipeline-first", "PIPELINE1");
var processor = new AeTitleJobProcessor(_configuration, _notificationService, _loggerFactory.Object, _jobStore.Object, _cleanupQueue.Object, _dicomToolkit.Object, _cancellationTokenSource.Token);
_cancellationTokenSource.CancelAfter(250);
Thread.Sleep(3000);
_logger.VerifyLoggingMessageBeginsWith($"AE Title Job Processor canceled", LogLevel.Warning, Times.Once());
}
public void InitializeSettings_ShallUseDefaultIfNotSpecified()
{
_configuration.AeTitle = "AET1";
_configuration.ProcessorSettings.Add("pipeline-test", "PIPELINEID");
_configuration.ProcessorSettings.Add("priority", "higher");
var processor = new AeTitleJobProcessor(_configuration, _notificationService, _loggerFactory.Object, _jobStore.Object, _cleanupQueue.Object, _dicomToolkit.Object, _cancellationTokenSource.Token);
_logger.VerifyLogging($"AE Title AET1 Processor Setting: timeout={AeTitleJobProcessor.DEFAULT_TIMEOUT_SECONDS}s", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"AE Title AET1 Processor Setting: groupBy={DicomTag.StudyInstanceUID}", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"AE Title AET1 Processor Setting: priority={JobPriority.Higher}", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"Pipeline test=PIPELINEID added for AE Title AET1", LogLevel.Information, Times.Once());
}
public void InitializeSettings_ThrowsIfNoPipelineDefined()
{
_configuration.AeTitle = "AET1";
var exception = Assert.Throws <ConfigurationException>(() =>
{
var processor = new AeTitleJobProcessor(_configuration, _notificationService, _loggerFactory.Object, _jobStore.Object, _cleanupQueue.Object, _dicomToolkit.Object, _cancellationTokenSource.Token);
});
Assert.Equal("No pipeline defined for AE Title AET1", exception.Message);
_logger.VerifyLogging($"AE Title AET1 Processor Setting: timeout={AeTitleJobProcessor.DEFAULT_TIMEOUT_SECONDS}s", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"AE Title AET1 Processor Setting: groupBy={DicomTag.StudyInstanceUID}", LogLevel.Information, Times.Once());
}
public void ProcessJobs_ShallIgnoreInstancesWithoutSpeicifiedDicomTag()
{
string expectedValue = string.Empty;
_dicomToolkit.Reset();
_dicomToolkit.Setup(p => p.TryGetString(It.IsAny <string>(), It.IsAny <DicomTag>(), out expectedValue)).Returns(false);
_configuration.AeTitle = _aeTitle;
_configuration.ProcessorSettings.Add("timeout", "1");
_configuration.ProcessorSettings.Add("jobRetryDelay", "100");
_configuration.ProcessorSettings.Add("pipeline-first", "PIPELINE1");
var processor = new AeTitleJobProcessor(_configuration, _notificationService, _loggerFactory.Object, _jobStore.Object, _cleanupQueue.Object, _dicomToolkit.Object, _cancellationTokenSource.Token);
_notificationService.NewInstanceStored(_instances.First());
Thread.Sleep(500);
_dicomToolkit.Verify(p => p.TryGetString(It.IsAny <string>(), It.IsAny <DicomTag>(), out expectedValue), Times.Once());
_logger.VerifyLogging($"Instance missing required DICOM key for grouping by {DicomTag.StudyInstanceUID}, ignoring", LogLevel.Error, Times.Once());
}
public void TriggerJobsWithGroupingAndPriority(string dicomTag, JobPriority jobPriority)
{
var grouping = DicomTag.Parse(dicomTag);
_jobStore.Setup(p => p.Add(It.IsAny <InferenceJob>()));
var countdownEvent = new CountdownEvent(_instances.Count);
_cleanupQueue.Setup(p => p.QueueInstance(It.IsAny <string>())).Callback((string path) =>
{
countdownEvent.Signal();
});
_configuration.AeTitle = _aeTitle;
_configuration.ProcessorSettings.Add("timeout", "1");
_configuration.ProcessorSettings.Add("groupBy", grouping.ToString());
_configuration.ProcessorSettings.Add("priority", jobPriority.ToString());
_configuration.ProcessorSettings.Add("pipeline-first", "PIPELINE1");
_configuration.ProcessorSettings.Add("pipeline-second", "PIPELINE2");
var processor = new AeTitleJobProcessor(_configuration, _notificationService, _loggerFactory.Object, _jobStore.Object, _cleanupQueue.Object, _dicomToolkit.Object, _cancellationTokenSource.Token);
foreach (var instance in _instances)
{
_notificationService.NewInstanceStored(instance);
}
countdownEvent.Wait(System.TimeSpan.FromSeconds(60));
// Verify configuration
_logger.VerifyLogging($"AE Title AET1 Processor Setting: timeout={AeTitleJobProcessor.DEFAULT_TIMEOUT_SECONDS}s", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"AE Title AET1 Processor Setting: priority={jobPriority.ToString()}", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"AE Title AET1 Processor Setting: groupBy={grouping}", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"Pipeline first=PIPELINE1 added for AE Title {_aeTitle}", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"Pipeline second=PIPELINE2 added for AE Title {_aeTitle}", LogLevel.Information, Times.Once());
// Verify notified instances
switch (dicomTag)
{
case "00100020":
_logger.VerifyLogging($"Instance received and added with key {_patient1}", LogLevel.Debug, Times.Exactly(3));
_logger.VerifyLogging($"Instance received and added with key {_patient2}", LogLevel.Debug, Times.Exactly(1));
break;
case "0020000D":
_logger.VerifyLogging($"Instance received and added with key {_study1.UID}", LogLevel.Debug, Times.Exactly(2));
_logger.VerifyLogging($"Instance received and added with key {_study2.UID}", LogLevel.Debug, Times.Exactly(1));
_logger.VerifyLogging($"Instance received and added with key {_study3.UID}", LogLevel.Debug, Times.Exactly(1));
break;
case "0020000E":
_logger.VerifyLogging($"Instance received and added with key {_series1.UID}", LogLevel.Debug, Times.Exactly(1));
_logger.VerifyLogging($"Instance received and added with key {_series2.UID}", LogLevel.Debug, Times.Exactly(1));
_logger.VerifyLogging($"Instance received and added with key {_series3.UID}", LogLevel.Debug, Times.Exactly(1));
_logger.VerifyLogging($"Instance received and added with key {_series4.UID}", LogLevel.Debug, Times.Exactly(1));
break;
}
// Verify timer events
switch (dicomTag)
{
case "00100020":
_logger.VerifyLogging($"New collection created for {_patient1}", LogLevel.Debug, Times.Once());
_logger.VerifyLogging($"New collection created for {_patient2}", LogLevel.Debug, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_patient1}", LogLevel.Information, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_patient2}", LogLevel.Information, Times.Once());
break;
case "0020000D":
_logger.VerifyLogging($"New collection created for {_study1.UID}", LogLevel.Debug, Times.Once());
_logger.VerifyLogging($"New collection created for {_study2.UID}", LogLevel.Debug, Times.Once());
_logger.VerifyLogging($"New collection created for {_study3.UID}", LogLevel.Debug, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_study1.UID}", LogLevel.Information, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_study2.UID}", LogLevel.Information, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_study3.UID}", LogLevel.Information, Times.Once());
break;
case "0020000E":
_logger.VerifyLogging($"New collection created for {_series1.UID}", LogLevel.Debug, Times.Once());
_logger.VerifyLogging($"New collection created for {_series2.UID}", LogLevel.Debug, Times.Once());
_logger.VerifyLogging($"New collection created for {_series3.UID}", LogLevel.Debug, Times.Once());
_logger.VerifyLogging($"New collection created for {_series4.UID}", LogLevel.Debug, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_series1.UID}", LogLevel.Information, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_series2.UID}", LogLevel.Information, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_series3.UID}", LogLevel.Information, Times.Once());
_logger.VerifyLoggingMessageBeginsWith($"Timeout elapsed waiting for {grouping} {_series4.UID}", LogLevel.Information, Times.Once());
break;
}
// Verify jobs generated
switch (dicomTag)
{
case "00100020":
_logger.VerifyLogging($"Job generated {_aeTitle}-first-{_patient1} for pipeline PIPELINE1", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"Job generated {_aeTitle}-second-{_patient1} for pipeline PIPELINE2", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"Job generated {_aeTitle}-first-{_patient2} for pipeline PIPELINE1", LogLevel.Information, Times.Once());
_logger.VerifyLogging($"Job generated {_aeTitle}-second-{_patient2} for pipeline PIPELINE2", LogLevel.Information, Times.Once());
break;
case "0020000D":
_logger.VerifyLogging($"Job generated {_aeTitle}-first-{_patient1} for pipeline PIPELINE1", LogLevel.Information, Times.Exactly(2));
_logger.VerifyLogging($"Job generated {_aeTitle}-second-{_patient1} for pipeline PIPELINE2", LogLevel.Information, Times.Exactly(2));
_logger.VerifyLogging($"Job generated {_aeTitle}-first-{_patient2} for pipeline PIPELINE1", LogLevel.Information, Times.Exactly(1));
_logger.VerifyLogging($"Job generated {_aeTitle}-second-{_patient2} for pipeline PIPELINE2", LogLevel.Information, Times.Exactly(1));
break;
case "0020000E":
_logger.VerifyLogging($"Job generated {_aeTitle}-first-{_patient1} for pipeline PIPELINE1", LogLevel.Information, Times.Exactly(3));
_logger.VerifyLogging($"Job generated {_aeTitle}-second-{_patient1} for pipeline PIPELINE2", LogLevel.Information, Times.Exactly(3));
_logger.VerifyLogging($"Job generated {_aeTitle}-first-{_patient2} for pipeline PIPELINE1", LogLevel.Information, Times.Exactly(1));
_logger.VerifyLogging($"Job generated {_aeTitle}-second-{_patient2} for pipeline PIPELINE2", LogLevel.Information, Times.Exactly(1));
break;
}
// Verify new pipeline job events
switch (dicomTag)
{
case "00100020":
_logger.VerifyLoggingMessageBeginsWith($"Submitting a new job", LogLevel.Information, Times.Exactly(4));
_logger.VerifyLogging($"Uploading 3 instances", LogLevel.Information, Times.Exactly(2));
_logger.VerifyLogging($"Uploading 1 instances", LogLevel.Information, Times.Exactly(2));
_logger.VerifyLogging($"Upload to payload completed", LogLevel.Information, Times.Exactly(4));
_jobStore.Verify(p => p.Add(It.IsAny <InferenceJob>()), Times.Exactly(4));
break;
case "0020000D":
_logger.VerifyLoggingMessageBeginsWith($"Submitting a new job", LogLevel.Information, Times.Exactly(6));
_logger.VerifyLogging($"Uploading 2 instances", LogLevel.Information, Times.Exactly(2));
_logger.VerifyLogging($"Uploading 1 instances", LogLevel.Information, Times.Exactly(4));
_logger.VerifyLogging($"Upload to payload completed", LogLevel.Information, Times.Exactly(6));
_jobStore.Verify(p => p.Add(It.IsAny <InferenceJob>()), Times.Exactly(6));
break;
case "0020000E":
_logger.VerifyLoggingMessageBeginsWith($"Submitting a new job", LogLevel.Information, Times.Exactly(8));
_logger.VerifyLogging($"Uploading 1 instances", LogLevel.Information, Times.Exactly(8));
_logger.VerifyLogging($"Upload to payload completed", LogLevel.Information, Times.Exactly(8));
_jobStore.Verify(p => p.Add(It.IsAny <InferenceJob>()), Times.Exactly(8));
break;
}
// Verify cleanups
switch (dicomTag)
{
case "00100020":
_logger.VerifyLoggingMessageBeginsWith($"Notifying Disk Reclaimer to delete", LogLevel.Debug, Times.Exactly(2));
_logger.VerifyLoggingMessageBeginsWith($"Notified Disk Reclaimer to delete", LogLevel.Information, Times.Exactly(2));
break;
case "0020000D":
_logger.VerifyLoggingMessageBeginsWith($"Notifying Disk Reclaimer to delete", LogLevel.Debug, Times.Exactly(3));
_logger.VerifyLoggingMessageBeginsWith($"Notified Disk Reclaimer to delete", LogLevel.Information, Times.Exactly(3));
break;
case "0020000E":
_logger.VerifyLoggingMessageBeginsWith($"Notifying Disk Reclaimer to delete", LogLevel.Debug, Times.Exactly(4));
_logger.VerifyLoggingMessageBeginsWith($"Notified Disk Reclaimer to delete", LogLevel.Information, Times.Exactly(4));
break;
}
foreach (var instance in _instances)
{
_cleanupQueue.Verify(p => p.QueueInstance(instance.InstanceStorageFullPath), Times.Once());
}
}