SSDM-2054: "Finalizer counts the time from the end of the primary archiving...

SSDM-2054: "Finalizer counts the time from the end of the primary archiving job and not when it is started." implemented but produces confusing log messages.

SVN: 34332

common/source/java/ch/systemsx/cisd/common/utilities/WaitingHelper.java

@@ -77,13 +77,24 @@ public class WaitingHelper
      */
     public boolean waitOn(IWaitingCondition condition)
     {
-        long t0 = provider.getTimeInMilliseconds();
-        long t = t0;
-        long lastLogTime = t0;
+        return waitOn(provider.getTimeInMilliseconds(), condition);
+    }
+
+    /**
+     * Waits until specified condition is fulfilled.
+     * 
+     * @param startTime Start time. Waiting times out after startTime + timeOut.
+     *      * @return <code>true</code> if waiting stops because condition has been fulfilled. 
+     *      If this isn't the case after the specified time out <code>false</code> will be returned.
+     */
+    public boolean waitOn(long startTime, IWaitingCondition condition)
+    {
+        long t = startTime;
+        long lastLogTime = startTime;
         long logInterval = MINIMUM_LOG_INTERVAL;
-        while (t < t0 + timeOut)
+        while (t < startTime + timeOut)
         {
-            long duration = t - t0;
+            long duration = t - startTime;
             String renderedDuration = DateTimeUtils.renderDuration(duration);
             if (condition.conditionFulfilled())
             {

datastore_server/source/java/ch/systemsx/cisd/openbis/dss/generic/server/plugins/standard/archiver/MultiDataSetArchiver.java

@@ -18,6 +18,7 @@ package ch.systemsx.cisd.openbis.dss.generic.server.plugins.standard.archiver;
 
 import java.io.File;
 import java.io.Serializable;
+import java.text.SimpleDateFormat;
 import java.util.ArrayList;
 import java.util.HashMap;
 import java.util.Iterator;
@@ -347,7 +348,8 @@ public class MultiDataSetArchiver extends AbstractArchiverProcessingPlugin
         {
             return;
         }
-        MultiDataSetArchivingFinalizer task = new MultiDataSetArchivingFinalizer(cleanerProperties, SystemTimeProvider.SYSTEM_TIME_PROVIDER);
+        ITimeAndWaitingProvider timeProvider = SystemTimeProvider.SYSTEM_TIME_PROVIDER;
+        MultiDataSetArchivingFinalizer task = new MultiDataSetArchivingFinalizer(cleanerProperties, timeProvider);
         String userId = archiverContext.getUserId();
         String userEmail = archiverContext.getUserEmail();
         String userSessionToken = archiverContext.getUserSessionToken();
@@ -358,6 +360,8 @@ public class MultiDataSetArchiver extends AbstractArchiverProcessingPlugin
         parameterBindings.put(MultiDataSetArchivingFinalizer.REPLICATED_FILE_PATH_KEY, 
                 operations.getReplicatedArchiveFilePath(containerPath));
         parameterBindings.put(MultiDataSetArchivingFinalizer.FINALIZER_POLLING_TIME_KEY, Long.toString(finalizerPollingTime));
+        SimpleDateFormat dateFormat = new SimpleDateFormat(MultiDataSetArchivingFinalizer.TIME_STAMP_FORMAT);
+        parameterBindings.put(MultiDataSetArchivingFinalizer.START_TIME_KEY, dateFormat.format(timeProvider.getTimeInMilliseconds()));
         parameterBindings.put(MultiDataSetArchivingFinalizer.FINALIZER_MAX_WAITING_TIME_KEY, Long.toString(finalizerMaxWaitingTime));
         DataSetArchivingStatus status = removeFromDataStore ? DataSetArchivingStatus.ARCHIVED : DataSetArchivingStatus.AVAILABLE;
         parameterBindings.put(MultiDataSetArchivingFinalizer.STATUS_KEY, status.toString());

datastore_server/source/java/ch/systemsx/cisd/openbis/dss/generic/server/plugins/standard/archiver/MultiDataSetArchivingFinalizer.java

@@ -17,6 +17,8 @@
 package ch.systemsx.cisd.openbis.dss.generic.server.plugins.standard.archiver;
 
 import java.io.File;
+import java.text.ParseException;
+import java.text.SimpleDateFormat;
 import java.util.ArrayList;
 import java.util.List;
 import java.util.Map;
@@ -60,8 +62,11 @@ class MultiDataSetArchivingFinalizer implements IProcessingPluginTask
     public static final String REPLICATED_FILE_PATH_KEY = "replicated-file-path";
     public static final String FINALIZER_POLLING_TIME_KEY = "finalizer-polling-time";
     public static final String FINALIZER_MAX_WAITING_TIME_KEY = "finalizer-max-waiting-time";
+    public static final String START_TIME_KEY = "start-time";
     public static final String STATUS_KEY = "status";
     
+    public static final String TIME_STAMP_FORMAT = "yyyy-MM-dd HH:mm:ss";
+    
     private static final Logger operationLog = LogFactory.getLogger(LogCategory.OPERATION,
             MultiDataSetArchivingFinalizer.class);
 
@@ -165,7 +170,8 @@ class MultiDataSetArchivingFinalizer implements IProcessingPluginTask
         long waitingTime = parameters.getWaitingTime();
         Log4jSimpleLogger logger = new Log4jSimpleLogger(operationLog);
         WaitingHelper waitingHelper = new WaitingHelper(waitingTime, parameters.getPollingTime(), timeProvider, logger);
-        return waitingHelper.waitOn(new IWaitingCondition()
+        long startTime = parameters.getStartTime();
+        return waitingHelper.waitOn(startTime, new IWaitingCondition()
             {
                 @Override
                 public boolean conditionFulfilled()
@@ -201,11 +207,25 @@ class MultiDataSetArchivingFinalizer implements IProcessingPluginTask
         parameters.setOriginalFile(new File(getProperty(parameterBindings, ORIGINAL_FILE_PATH_KEY)));
         parameters.setReplicatedFile(new File(getProperty(parameterBindings, REPLICATED_FILE_PATH_KEY)));
         parameters.setPollingTime(getNumber(parameterBindings, FINALIZER_POLLING_TIME_KEY));
+        parameters.setStartTime(getTimestamp(parameterBindings, START_TIME_KEY));
         parameters.setWaitingTime(getNumber(parameterBindings, FINALIZER_MAX_WAITING_TIME_KEY));
         parameters.setStatus(DataSetArchivingStatus.valueOf(getProperty(parameterBindings, STATUS_KEY)));
         return parameters;
     }
     
+    private long getTimestamp(Map<String, String> parameterBindings, String property)
+    {
+        String value = getProperty(parameterBindings, property);
+        try
+        {
+            return new SimpleDateFormat(TIME_STAMP_FORMAT).parse(value).getTime();
+        } catch (ParseException ex)
+        {
+            throw new IllegalArgumentException("Property '" + property + "' isn't a time stamp of format " 
+                    + TIME_STAMP_FORMAT + ": " + value);
+        }
+    }
+    
     private long getNumber(Map<String, String> parameterBindings, String property)
     {
         String value = getProperty(parameterBindings, property);
@@ -234,6 +254,7 @@ class MultiDataSetArchivingFinalizer implements IProcessingPluginTask
         private File originalFile;
         private File replicatedFile;
         private long pollingTime;
+        private long startTime;
         private long waitingTime;
         private DataSetArchivingStatus status;
 
@@ -257,6 +278,16 @@ class MultiDataSetArchivingFinalizer implements IProcessingPluginTask
             return pollingTime;
         }
         
+        public long getStartTime()
+        {
+            return startTime;
+        }
+
+        public void setStartTime(long startTime)
+        {
+            this.startTime = startTime;
+        }
+
         public void setWaitingTime(long waitingTime)
         {
             this.waitingTime = waitingTime;

datastore_server/sourceTest/java/ch/systemsx/cisd/openbis/dss/generic/server/plugins/standard/archiver/MultiDataSetArchivingFinalizerTest.java

@@ -17,6 +17,7 @@
 package ch.systemsx.cisd.openbis.dss.generic.server.plugins.standard.archiver;
 
 import java.io.File;
+import java.text.SimpleDateFormat;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.LinkedHashMap;
@@ -55,6 +56,12 @@ import ch.systemsx.cisd.openbis.util.LogRecordingUtils;
  */
 public class MultiDataSetArchivingFinalizerTest extends AbstractFileSystemTestCase
 {
+    
+    private static final long START_TIME = 123456789012l;
+
+    private static final String START_TIME_AS_STRING 
+            = new SimpleDateFormat(MultiDataSetArchivingFinalizer.TIME_STAMP_FORMAT).format(START_TIME);
+
     private static final String USER_ID = "test-user";
 
     private static final String USER_EMAIL = "a@bc.de";
@@ -112,13 +119,14 @@ public class MultiDataSetArchivingFinalizerTest extends AbstractFileSystemTestCa
         parameterBindings.put(MultiDataSetArchivingFinalizer.ORIGINAL_FILE_PATH_KEY, dataFileInArchive.getPath());
         parameterBindings.put(MultiDataSetArchivingFinalizer.REPLICATED_FILE_PATH_KEY, dataFileReplicated.getPath());
         parameterBindings.put(MultiDataSetArchivingFinalizer.FINALIZER_POLLING_TIME_KEY, "20000");
+        parameterBindings.put(MultiDataSetArchivingFinalizer.START_TIME_KEY, START_TIME_AS_STRING);
         parameterBindings.put(MultiDataSetArchivingFinalizer.FINALIZER_MAX_WAITING_TIME_KEY, "300000");
         parameterBindings.put(MultiDataSetArchivingFinalizer.STATUS_KEY, DataSetArchivingStatus.ARCHIVED.toString());
         processingContext = new DataSetProcessingContext(null, null,
                 parameterBindings, null, USER_ID, USER_EMAIL);
         updatedStatus = new ArrayList<DataSetCodesWithStatus>();
         cleaner = new MockCleaner();
-        finalizer = new MultiDataSetArchivingFinalizer(null, new MockTimeProvider())
+        finalizer = new MultiDataSetArchivingFinalizer(null, new MockTimeProvider(START_TIME, 1000))
             {
                 private static final long serialVersionUID = 1L;
 
@@ -175,7 +183,8 @@ public class MultiDataSetArchivingFinalizerTest extends AbstractFileSystemTestCa
         assertEquals("INFO  OPERATION.MultiDataSetArchivingFinalizer - "
                 + "Parameters: {original-file-path=" + dataFileInArchive.getPath()
                 + ", replicated-file-path=" + dataFileReplicated.getPath() + ", "
-                + "finalizer-polling-time=20000, finalizer-max-waiting-time=300000, status=ARCHIVED}\n"
+                + "finalizer-polling-time=20000, start-time=" + START_TIME_AS_STRING + ", "
+                + "finalizer-max-waiting-time=300000, status=ARCHIVED}\n"
                 + "INFO  OPERATION.MultiDataSetArchivingFinalizer - Waiting for replication of archive "
                 + "'" + dataFileInArchive.getPath() + "' containing the following data sets: [ds1]\n"
                 + "INFO  OPERATION.MultiDataSetArchivingFinalizer - Condition fulfilled after < 1sec, condition: "
@@ -199,7 +208,8 @@ public class MultiDataSetArchivingFinalizerTest extends AbstractFileSystemTestCa
         assertEquals("INFO  OPERATION.MultiDataSetArchivingFinalizer - "
                 + "Parameters: {original-file-path=" + dataFileInArchive.getPath()
                 + ", replicated-file-path=" + dataFileReplicated.getPath() + ", "
-                + "finalizer-polling-time=20000, finalizer-max-waiting-time=300000, status=AVAILABLE}\n"
+                + "finalizer-polling-time=20000, start-time=" + START_TIME_AS_STRING + ", "
+                + "finalizer-max-waiting-time=300000, status=AVAILABLE}\n"
                 + "INFO  OPERATION.MultiDataSetArchivingFinalizer - Waiting for replication of archive "
                 + "'" + dataFileInArchive.getPath() + "' containing the following data sets: [ds1]\n"
                 + "INFO  OPERATION.MultiDataSetArchivingFinalizer - Condition fulfilled after < 1sec, condition: "
@@ -233,7 +243,8 @@ public class MultiDataSetArchivingFinalizerTest extends AbstractFileSystemTestCa
         assertEquals("INFO  OPERATION.MultiDataSetArchivingFinalizer - "
                 + "Parameters: {original-file-path=" + dataFileInArchive.getPath()
                 + ", replicated-file-path=" + dataFilePartiallyReplicated.getPath() + ", "
-                + "finalizer-polling-time=20000, finalizer-max-waiting-time=300000, status=ARCHIVED}\n"
+                + "finalizer-polling-time=20000, start-time=" + START_TIME_AS_STRING + ", "
+                + "finalizer-max-waiting-time=300000, status=ARCHIVED}\n"
                 + "INFO  OPERATION.MultiDataSetArchivingFinalizer - Waiting for replication of archive "
                 + "'" + dataFileInArchive.getPath() + "' containing the following data sets: [ds1, ds2]\n"
                 + "INFO  OPERATION.MultiDataSetArchivingFinalizer - Condition still not fulfilled after < 1sec, "
@@ -276,7 +287,8 @@ public class MultiDataSetArchivingFinalizerTest extends AbstractFileSystemTestCa
         assertEquals("INFO  OPERATION.MultiDataSetArchivingFinalizer - "
                 + "Parameters: {original-file-path=" + dataFileInArchive.getPath()
                 + ", replicated-file-path=" + dataFilePartiallyReplicated.getPath() + ", "
-                + "finalizer-polling-time=20000, finalizer-max-waiting-time=300000, status=AVAILABLE}\n"
+                + "finalizer-polling-time=20000, start-time=" + START_TIME_AS_STRING + ", "
+                + "finalizer-max-waiting-time=300000, status=AVAILABLE}\n"
                 + "INFO  OPERATION.MultiDataSetArchivingFinalizer - Waiting for replication of archive "
                 + "'" + dataFileInArchive.getPath() + "' containing the following data sets: [ds1, ds2]\n"
                 + "INFO  OPERATION.MultiDataSetArchivingFinalizer - Condition still not fulfilled after < 1sec, "