From 1636bbbf96df0902bc3f1ef4d58c4ce8ce04ef49 Mon Sep 17 00:00:00 2001
From: felmer <felmer>
Date: Mon, 19 May 2008 07:25:50 +0000
Subject: [PATCH] DMV-13 Improved logging, more tests
SVN: 6115
---
.../datamover/utils/DataCompletedFilter.java | 2 +-
.../cisd/datamover/IncomingProcessorTest.java | 120 +++++++++++++++++-
2 files changed, 116 insertions(+), 6 deletions(-)
diff --git a/datamover/source/java/ch/systemsx/cisd/datamover/utils/DataCompletedFilter.java b/datamover/source/java/ch/systemsx/cisd/datamover/utils/DataCompletedFilter.java
index fe299cbd2bf..e56ce321fd1 100644
--- a/datamover/source/java/ch/systemsx/cisd/datamover/utils/DataCompletedFilter.java
+++ b/datamover/source/java/ch/systemsx/cisd/datamover/utils/DataCompletedFilter.java
@@ -144,8 +144,8 @@ public class DataCompletedFilter implements IStoreItemFilter
} else
{
notificationLog.error(message);
- result.log();
}
+ result.log();
lastStatus = status;
}
return ok;
diff --git a/datamover/sourceTest/java/ch/systemsx/cisd/datamover/IncomingProcessorTest.java b/datamover/sourceTest/java/ch/systemsx/cisd/datamover/IncomingProcessorTest.java
index 9cc12c98ca9..5a8129824ea 100644
--- a/datamover/sourceTest/java/ch/systemsx/cisd/datamover/IncomingProcessorTest.java
+++ b/datamover/sourceTest/java/ch/systemsx/cisd/datamover/IncomingProcessorTest.java
@@ -16,10 +16,13 @@
package ch.systemsx.cisd.datamover;
+import static org.testng.AssertJUnit.assertEquals;
+
import java.io.File;
import java.io.IOException;
import java.util.TimerTask;
+import org.apache.log4j.Level;
import org.jmock.Expectations;
import org.jmock.Mockery;
import org.testng.annotations.AfterMethod;
@@ -27,10 +30,12 @@ import org.testng.annotations.BeforeMethod;
import org.testng.annotations.Test;
import ch.systemsx.cisd.common.highwatermark.FileWithHighwaterMark;
+import ch.systemsx.cisd.common.logging.BufferedAppender;
import ch.systemsx.cisd.common.logging.LogInitializer;
import ch.systemsx.cisd.common.utilities.FileUtilities;
import ch.systemsx.cisd.common.utilities.IExitHandler;
import ch.systemsx.cisd.common.utilities.MockTimeProvider;
+import ch.systemsx.cisd.common.utilities.OSUtilities;
import ch.systemsx.cisd.datamover.filesystem.intf.IFileSysOperationsFactory;
import ch.systemsx.cisd.datamover.filesystem.intf.IPathMover;
import ch.systemsx.cisd.datamover.filesystem.intf.IPathRemover;
@@ -43,13 +48,22 @@ import ch.systemsx.cisd.datamover.utils.LocalBufferDirs;
*/
public class IncomingProcessorTest
{
+ private static final String LOG_DEBUG_MACHINE_PREFIX = "DEBUG MACHINE.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - ";
+
+ private static final String LOG_DEBUG_PREFIX =
+ "DEBUG OPERATION.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - ";
+
private static final File TEST_FOLDER = new File("targets/unit-test/IncomingProcessorTest");
private static final String INCOMING_DIR = "incoming";
private static final String COPY_IN_PROGRESS_DIR = "copy-in-progress";
private static final String COPY_COMPLETE_DIR = "copy-complete";
private static final String READY_TO_MOVE_DIR = "ready-to-move";
private static final String TEMP_DIR = "temp";
+ private static final String EXAMPLE_SCRIPT_NAME = "example-script.sh";
+ private static final String EXAMPLE_SCRIPT = "echo hello world";
+ private static final File TEST_FILE = new File(TEST_FOLDER, "blabla.txt");
+ private BufferedAppender logRecorder;
private Mockery context;
private IFileSysOperationsFactory fileSysOpertationFactory;
private IPathMover mover;
@@ -64,6 +78,7 @@ public class IncomingProcessorTest
public void setUp()
{
LogInitializer.init();
+ logRecorder = new BufferedAppender("%-5p %c - %m%n", Level.DEBUG);
context = new Mockery();
fileSysOpertationFactory = context.mock(IFileSysOperationsFactory.class);
mover = context.mock(IPathMover.class);
@@ -72,8 +87,7 @@ public class IncomingProcessorTest
FileUtilities.deleteRecursively(TEST_FOLDER);
TEST_FOLDER.mkdirs();
- exampleScript = new File(TEST_FOLDER, "example");
- FileUtilities.writeToFile(exampleScript, "echo hello world");
+ exampleScript = new File(TEST_FOLDER, EXAMPLE_SCRIPT_NAME);
incomingDir = new File(TEST_FOLDER, INCOMING_DIR);
incomingDir.mkdir();
copyInProgressDir = new File(TEST_FOLDER, COPY_IN_PROGRESS_DIR);
@@ -87,13 +101,14 @@ public class IncomingProcessorTest
@AfterMethod
public void tearDown()
{
+ logRecorder.reset();
// To following line of code should also be called at the end of each test method.
// Otherwise one do not known which test failed.
context.assertIsSatisfied();
}
@Test
- public void testHappyCaseWithoutDataCompletedScript() throws IOException
+ public void testWithoutDataCompletedScript() throws IOException
{
final File testDataFile = new File(incomingDir, "test-data.txt");
testDataFile.createNewFile();
@@ -111,13 +126,15 @@ public class IncomingProcessorTest
dataMoverTimerTask.run(); // 1. round finds a file to process
dataMoverTimerTask.run(); // 2. round finds that quiet period is over
+ assertEquals("", getNormalizedLogContent());
+
context.assertIsSatisfied();
}
-
@Test
- public void testHappyCaseWithDataCompletedScript() throws IOException
+ public void testWithDataCompletedScript() throws IOException
{
+ FileUtilities.writeToFile(exampleScript, EXAMPLE_SCRIPT);
final File testDataFile = new File(incomingDir, "test-data.txt");
testDataFile.createNewFile();
context.checking(new Expectations()
@@ -134,9 +151,102 @@ public class IncomingProcessorTest
TimerTask dataMoverTimerTask = process.getDataMoverTimerTask();
dataMoverTimerTask.run(); // 1. round finds a file to process
dataMoverTimerTask.run(); // 2. round finds that quiet period is over
+ dataMoverTimerTask.run(); // 3. round does not change status, thus no log
+
+ assertEquals(
+ LOG_DEBUG_PREFIX
+ + "Executing command: [sh, targets/unit-test/IncomingProcessorTest/example-script.sh, "
+ + "<wd>/targets/unit-test/IncomingProcessorTest/incoming/test-data.txt]"
+ + OSUtilities.LINE_SEPARATOR
+ + "INFO NOTIFY.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - "
+ + "Processing status of data completed script has changed to "
+ + "DataCompletedFilter.Status{ok=true,run=true,terminated=false,exitValue=0,blocked=false}. "
+ + "Command line: [sh, targets/unit-test/IncomingProcessorTest/example-script.sh, "
+ + "<wd>/targets/unit-test/IncomingProcessorTest/incoming/test-data.txt]"
+ + OSUtilities.LINE_SEPARATOR + LOG_DEBUG_PREFIX
+ + "[sh] process returned with exit value 0." + OSUtilities.LINE_SEPARATOR
+ + LOG_DEBUG_MACHINE_PREFIX + "[sh] output:" + OSUtilities.LINE_SEPARATOR
+ + LOG_DEBUG_MACHINE_PREFIX + "\"hello world\"", getNormalizedLogContent());
+
+ context.assertIsSatisfied();
+ }
+
+ @Test
+ public void testWithDataCompletedScriptWhichFailsInitially() throws IOException
+ {
+ FileUtilities.writeToFile(exampleScript, EXAMPLE_SCRIPT + "\nrm -v "
+ + TEST_FILE.toString().replace('\\', '/'));
+ final File testDataFile = new File(incomingDir, "test-data.txt");
+ testDataFile.createNewFile();
+ context.checking(new Expectations()
+ {
+ {
+ one(mover).tryMove(testDataFile, copyCompleteDir, "");
+ will(returnValue(new File(copyCompleteDir, testDataFile.getName())));
+ }
+ });
+
+ DataMoverProcess process =
+ createProcess("--" + PropertyNames.INCOMING_DIR, incomingDir.toString(), "-q", "1",
+ "--" + PropertyNames.DATA_COMPLETED_SCRIPT, exampleScript.toString());
+ TimerTask dataMoverTimerTask = process.getDataMoverTimerTask();
+ dataMoverTimerTask.run(); // 1. round finds a file to process
+ dataMoverTimerTask.run(); // 2. round finds that quiet period is over
+ dataMoverTimerTask.run(); // 3. round does not change status, thus no log
+ TEST_FILE.createNewFile();
+ dataMoverTimerTask.run(); // 4. round finds changed status, thus log
+
+ assertEquals(
+ LOG_DEBUG_PREFIX
+ + "Executing command: [sh, targets/unit-test/IncomingProcessorTest/example-script.sh, "
+ + "<wd>/targets/unit-test/IncomingProcessorTest/incoming/test-data.txt]"
+ + OSUtilities.LINE_SEPARATOR
+ + "ERROR NOTIFY.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - "
+ + "Processing status of data completed script has changed to "
+ + "DataCompletedFilter.Status{ok=false,run=true,terminated=true,exitValue=1,blocked=false}. "
+ + "Command line: [sh, targets/unit-test/IncomingProcessorTest/example-script.sh, "
+ + "<wd>/targets/unit-test/IncomingProcessorTest/incoming/test-data.txt]"
+ + OSUtilities.LINE_SEPARATOR
+ + "WARN OPERATION.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - "
+ + "[sh] process was destroyed."
+ + OSUtilities.LINE_SEPARATOR
+ + "WARN MACHINE.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - "
+ + "[sh] output:"
+ + OSUtilities.LINE_SEPARATOR
+ + "WARN MACHINE.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - "
+ + "\"hello world\""
+ + OSUtilities.LINE_SEPARATOR
+ + "WARN MACHINE.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - "
+ + "\"rm: cannot remove `targets/unit-test/IncomingProcessorTest/blabla.txt': "
+ + "No such file or directory\""
+ + OSUtilities.LINE_SEPARATOR
+ + LOG_DEBUG_PREFIX
+ + "Executing command: [sh, targets/unit-test/IncomingProcessorTest/example-script.sh, "
+ + "<wd>/targets/unit-test/IncomingProcessorTest/incoming/test-data.txt]"
+ + OSUtilities.LINE_SEPARATOR
+ + "INFO NOTIFY.ch.systemsx.cisd.datamover.utils.DataCompletedFilter - "
+ + "Processing status of data completed script has changed to "
+ + "DataCompletedFilter.Status{ok=true,run=true,terminated=false,exitValue=0,blocked=false}. "
+ + "Command line: [sh, targets/unit-test/IncomingProcessorTest/example-script.sh, "
+ + "<wd>/targets/unit-test/IncomingProcessorTest/incoming/test-data.txt]"
+ + OSUtilities.LINE_SEPARATOR + LOG_DEBUG_PREFIX
+ + "[sh] process returned with exit value 0." + OSUtilities.LINE_SEPARATOR
+ + LOG_DEBUG_MACHINE_PREFIX + "[sh] output:" + OSUtilities.LINE_SEPARATOR
+ + LOG_DEBUG_MACHINE_PREFIX + "\"hello world\"" + OSUtilities.LINE_SEPARATOR
+ + LOG_DEBUG_MACHINE_PREFIX
+ + "\"removed `targets/unit-test/IncomingProcessorTest/blabla.txt'\"",
+ getNormalizedLogContent());
context.assertIsSatisfied();
}
+
+ private String getNormalizedLogContent()
+ {
+ String content = logRecorder.getLogContent();
+ content = content.replace(new File(System.getProperty("user.dir")).getAbsolutePath(), "<wd>");
+ content = content.replace('\\', '/');
+ return content;
+ }
private DataMoverProcess createProcess(String... args)
{
--
GitLab