diff --git a/common/source/java/ch/systemsx/cisd/common/filesystem/DirectoryScannedStore.java b/common/source/java/ch/systemsx/cisd/common/filesystem/DirectoryScannedStore.java index 5c32e57411383795ff9a6157bc30439b231b37ed..52b68764ebde37491395deaf1a58d3118a6c94bd 100644 --- a/common/source/java/ch/systemsx/cisd/common/filesystem/DirectoryScannedStore.java +++ b/common/source/java/ch/systemsx/cisd/common/filesystem/DirectoryScannedStore.java @@ -72,7 +72,7 @@ public final class DirectoryScannedStore implements IScannedStore } } - public StoreItem[] filterReadyToProcess(StoreItem[] items, ISimpleLogger loggerOrNull) + public StoreItem[] tryFilterReadyToProcess(StoreItem[] items, ISimpleLogger loggerOrNull) { StoreItem currentItem = null; try diff --git a/common/source/java/ch/systemsx/cisd/common/filesystem/DirectoryScanningTimerTask.java b/common/source/java/ch/systemsx/cisd/common/filesystem/DirectoryScanningTimerTask.java index d2bd7e269706208e98131fbb75cec254d2b24acb..b1adb3844d62b7f47a0e5416e19da00a8cc8202e 100644 --- a/common/source/java/ch/systemsx/cisd/common/filesystem/DirectoryScanningTimerTask.java +++ b/common/source/java/ch/systemsx/cisd/common/filesystem/DirectoryScanningTimerTask.java @@ -32,6 +32,7 @@ import org.apache.log4j.Level; import org.apache.log4j.Logger; import ch.systemsx.cisd.base.exceptions.InterruptedExceptionUnchecked; +import ch.systemsx.cisd.base.exceptions.TimeoutExceptionUnchecked; import ch.systemsx.cisd.common.collections.CollectionUtils; import ch.systemsx.cisd.common.exceptions.Status; import ch.systemsx.cisd.common.filesystem.IDirectoryScanningHandler.HandleInstruction; @@ -169,8 +170,8 @@ public final class DirectoryScanningTimerTask extends TimerTask implements ITime final IPathHandler pathHandler, final int ignoredErrorCount) { this(asScannedStore(sourceDirectory, fileFilter), new FaultyPathDirectoryScanningHandler( - sourceDirectory, pathHandler), PathHandlerAdapter - .asScanningHandler(sourceDirectory, pathHandler), ignoredErrorCount); + sourceDirectory, pathHandler), PathHandlerAdapter.asScanningHandler( + sourceDirectory, pathHandler), ignoredErrorCount); } private final static IScannedStore asScannedStore(final File directory, final FileFilter filter) @@ -180,7 +181,13 @@ public final class DirectoryScanningTimerTask extends TimerTask implements ITime private final void printNotification(final Exception ex) { - notificationLog.error("An exception has occurred. (thread still running)", ex); + if (ex instanceof TimeoutExceptionUnchecked) + { + notificationLog.error("Timeout while scanning directory: " + ex.getMessage(), ex); + } else + { + notificationLog.error("An exception has occurred. (thread still running)", ex); + } } private final StoreItem[] listStoreItems() @@ -225,32 +232,70 @@ public final class DirectoryScanningTimerTask extends TimerTask implements ITime { numberOfItemsProcessedInLastRound = 0; final StoreItem[] allStoreItems = listStoreItems(); + if (operationLog.isTraceEnabled()) + { + operationLog.trace(String.format("Found %d store items in total.", + allStoreItems.length)); + } cleanseErrorLog(allStoreItems); - final StoreItem[] storeItems = - sourceDirectory.filterReadyToProcess(allStoreItems, notificationLogger); - if (storeItems == null) + if (operationLog.isTraceEnabled()) + { + operationLog.trace(String.format( + "Found %d store items that are not in error state.", + allStoreItems.length)); + } + final StoreItem[] storeItemsOrNull = + sourceDirectory.tryFilterReadyToProcess(allStoreItems, notificationLogger); + if (operationLog.isTraceEnabled()) + { + operationLog.trace(String.format("Found %d store items ready to be processed.", + (storeItemsOrNull == null) ? 0 : storeItemsOrNull.length)); + } + if (storeItemsOrNull == null) { break; } - final int numberOfItems = storeItems.length; + final int numberOfItems = storeItemsOrNull.length; directoryScanningHandler.beforeHandle(); + if (operationLog.isTraceEnabled()) + { + operationLog.trace("beforeHandle() completed."); + } for (int i = 0; i < numberOfItems; i++) { - final StoreItem storeItem = storeItems[i]; + final StoreItem storeItem = storeItemsOrNull[i]; + if (operationLog.isTraceEnabled()) + { + operationLog.trace(String + .format("Looping over store item '%s'.", storeItem)); + } if (stopRun || Thread.interrupted() || storeHandler.isStopped()) { if (operationLog.isDebugEnabled()) { - operationLog.debug(String.format( - "Scan of store '%s' has been cancelled. " + operationLog + .debug(String.format("Scan of store '%s' has been cancelled. " + "Following items have NOT been handled: %s.", - sourceDirectory, CollectionUtils.abbreviate(ArrayUtils - .subarray(storeItems, i + 1, numberOfItems), 10))); + sourceDirectory, CollectionUtils.abbreviate(ArrayUtils + .subarray(storeItemsOrNull, i + 1, + numberOfItems), 10))); } return; } final HandleInstruction instruction = directoryScanningHandler.mayHandle(sourceDirectory, storeItem); + if (operationLog.isTraceEnabled()) + { + if (instruction.tryGetMessage() == null) + { + operationLog.trace(String.format("Handle instruction: %s.", instruction + .getFlag())); + } else + { + operationLog.trace(String.format("Handle instruction: %s [%s].", + instruction.getFlag(), instruction.tryGetMessage())); + } + } if (HandleInstructionFlag.PROCESS.equals(instruction.getFlag())) { try @@ -385,11 +430,11 @@ public final class DirectoryScanningTimerTask extends TimerTask implements ITime * @returns Only those <var>items</var> which are ready to be processed right now, or * <code>null</code>, if the filtering step produced an exception. */ - StoreItem[] filterReadyToProcess(final StoreItem[] items, ISimpleLogger loggerOrNull); + StoreItem[] tryFilterReadyToProcess(final StoreItem[] items, ISimpleLogger loggerOrNull); /** - * Returns <code>true</code>, if the <var>item</var> either still exists or is in an - * error state. + * Returns <code>true</code>, if the <var>item</var> either still exists or is in an error + * state. */ boolean existsOrError(StoreItem item); diff --git a/datamover/source/java/ch/systemsx/cisd/datamover/FileScannedStore.java b/datamover/source/java/ch/systemsx/cisd/datamover/FileScannedStore.java index 7ec9cc3768580ea857fb0e0ed8ede40038b29ade..7088a2886a68482321df01c8e36ace02e7f1c1f5 100644 --- a/datamover/source/java/ch/systemsx/cisd/datamover/FileScannedStore.java +++ b/datamover/source/java/ch/systemsx/cisd/datamover/FileScannedStore.java @@ -84,7 +84,7 @@ final class FileScannedStore implements IScannedStore return items; } - public final StoreItem[] filterReadyToProcess(final StoreItem[] items, + public final StoreItem[] tryFilterReadyToProcess(final StoreItem[] items, ISimpleLogger loggerOrNull) { StoreItem currentItem = null; diff --git a/datamover/source/java/ch/systemsx/cisd/datamover/filesystem/FileStoreFactory.java b/datamover/source/java/ch/systemsx/cisd/datamover/filesystem/FileStoreFactory.java index 7ff1a35a96affc78304a731d12d1765ec0440ef0..76ab3e332d9d14e6905fd889419858a966ddaedb 100644 --- a/datamover/source/java/ch/systemsx/cisd/datamover/filesystem/FileStoreFactory.java +++ b/datamover/source/java/ch/systemsx/cisd/datamover/filesystem/FileStoreFactory.java @@ -18,8 +18,12 @@ package ch.systemsx.cisd.datamover.filesystem; import java.io.File; +import org.apache.log4j.Logger; + import ch.rinn.restrictions.Private; import ch.systemsx.cisd.common.highwatermark.HostAwareFileWithHighwaterMark; +import ch.systemsx.cisd.common.logging.LogCategory; +import ch.systemsx.cisd.common.logging.LogFactory; import ch.systemsx.cisd.datamover.filesystem.intf.AbstractFileStore; import ch.systemsx.cisd.datamover.filesystem.intf.IFileStore; import ch.systemsx.cisd.datamover.filesystem.intf.IFileSysOperationsFactory; @@ -34,6 +38,9 @@ import ch.systemsx.cisd.datamover.filesystem.store.FileStoreRemoteMounted; */ public final class FileStoreFactory { + private static final Logger operationLog = + LogFactory.getLogger(LogCategory.OPERATION, FileStoreFactory.class); + private FileStoreFactory() { // This class can not be instantiated. @@ -98,16 +105,36 @@ public final class FileStoreFactory { if (path.tryGetHost() != null) { + if (operationLog.isDebugEnabled()) + { + operationLog.debug(String.format( + "Create %s store for remote host %s, path %s, timeout: %f s.", kind, path + .tryGetHost(), path.getFile().toString(), + FileStoreRemote.LONG_SSH_TIMEOUT_MILLIS / 1000.0)); + } return createRemoteHost(path, kind, factory, skipAccessibilityTest, findExecutableOrNull, lastchangedExecutableOrNull); } else { + final long timoutMillis = checkIntervalMillis * 3; if (isRemote) { + if (operationLog.isDebugEnabled()) + { + operationLog.debug(String.format( + "Create %s store for mounted path %s, timeout: %f s.", kind, path + .getFile().toString(), timoutMillis / 1000.0)); + } return new FileStoreRemoteMounted(path, kind, factory, skipAccessibilityTest, - checkIntervalMillis * 3); + timoutMillis); } else { + if (operationLog.isDebugEnabled()) + { + operationLog.debug(String.format( + "Create %s store for local path %s.", kind, path + .getFile().toString())); + } return createLocal(path, kind, factory, skipAccessibilityTest); } } diff --git a/datamover/source/java/ch/systemsx/cisd/datamover/filesystem/store/FileStoreRemote.java b/datamover/source/java/ch/systemsx/cisd/datamover/filesystem/store/FileStoreRemote.java index 31191106862d86712b4b1b2017d891eac7f09118..3e4ade2adafba8a69a02321c3755d7717f8fe403 100644 --- a/datamover/source/java/ch/systemsx/cisd/datamover/filesystem/store/FileStoreRemote.java +++ b/datamover/source/java/ch/systemsx/cisd/datamover/filesystem/store/FileStoreRemote.java @@ -56,9 +56,9 @@ public class FileStoreRemote extends AbstractFileStore private static final String NO_SUCH_FILE_OR_DIRECTORY_MSG = "No such file or directory"; - private static final long QUICK_SSH_TIMEOUT_MILLIS = 15 * 1000; + public static final long QUICK_SSH_TIMEOUT_MILLIS = 15 * 1000; - private static final long LONG_SSH_TIMEOUT_MILLIS = 120 * 1000; + public static final long LONG_SSH_TIMEOUT_MILLIS = 120 * 1000; // -- bash commands -------------