Reenable logging. Ref. icatproject/ids.server#76.

Author: RKrahl

pom.xml

@@ -40,7 +40,19 @@
 
     <dependencies>
 
-        <dependency>
+	<dependency>
+	    <groupId>org.slf4j</groupId>
+	    <artifactId>slf4j-api</artifactId>
+	    <version>1.7.7</version>
+	</dependency>
+
+	<dependency>
+	    <groupId>ch.qos.logback</groupId>
+	    <artifactId>logback-classic</artifactId>
+	    <version>1.1.3</version>
+	</dependency>
+
+	<dependency>
             <groupId>org.icatproject</groupId>
             <artifactId>icat.utils</artifactId>
             <version>4.16.0</version>
@@ -75,6 +87,9 @@
                     <artifactSet>
                         <includes>
                             <include>org.icatproject:ids.plugin</include>
+			    <include>org.slf4j:slf4j-api</include>
+			    <include>ch.qos.logback:logback-classic</include>
+			    <include>ch.qos.logback:logback-core</include>
                         </includes>
                     </artifactSet>
                 </configuration>

src/main/config/logback.xml.example

@@ -0,0 +1,28 @@
+<configuration>
+
+	<appender name="FILE"
+		class="ch.qos.logback.core.rolling.RollingFileAppender">
+		<file>${HOME}/logs/ids.log</file>
+		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+			<fileNamePattern>${HOME}/logs/ids.log.%d{yyyy-MM-dd}.%i.zip
+			</fileNamePattern>
+			<maxHistory>30</maxHistory>
+			<timeBasedFileNamingAndTriggeringPolicy
+				class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
+				<maxFileSize>100MB</maxFileSize>
+			</timeBasedFileNamingAndTriggeringPolicy>
+		</rollingPolicy>
+
+		<encoder>
+			<pattern>%date %level [%thread] %C{0} - %msg%n
+			</pattern>
+		</encoder>
+	</appender>
+
+	<root level="INFO">
+		<appender-ref ref="FILE" />
+	</root>
+
+	<logger name="org.icatproject.ids.FileChecker" level="INFO" />
+
+</configuration>

src/main/java/org/icatproject/site/hzb/ids/storage/ArchiveFileStorage.java

@@ -12,12 +12,18 @@
 import java.nio.file.StandardCopyOption;
 import java.util.Properties;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import org.icatproject.ids.plugin.AbstractArchiveStorage;
 import org.icatproject.ids.plugin.DsInfo;
 
 
 public class ArchiveFileStorage extends AbstractArchiveStorage {
 
+    private static final Logger logger
+	= LoggerFactory.getLogger(ArchiveFileStorage.class);
+
     private static final int BUFFER_SIZE = 65536;
 
     private Path baseDir;
@@ -38,6 +44,7 @@ public ArchiveFileStorage(Properties properties) throws IOException {
 	if (props.has("plugin.archive.filelock")) {
 	    doFileLocking = props.getBoolean("plugin.archive.filelock");
 	}
+	logger.info("ArchiveFileStorage initialized");
     }
 
     private String getRelPath(DsInfo dsInfo) {
@@ -59,14 +66,18 @@ public void put(DsInfo dsInfo, InputStream inputStream) throws IOException {
 	Path path = baseDir.resolve(getRelPath(dsInfo));
 	fileHelper.createDirectories(path.getParent());
 	if (doFileLocking) {
-	    try (FileOutputStream out = new FileOutputStream(path.toString())) {
+	    String outpath = path.toString();
+	    try (FileOutputStream out = new FileOutputStream(outpath)) {
 		FileChannel ch = out.getChannel();
+		logger.debug("Try to acquire an exclusive lock on {}.",outpath);
 		try (FileLock lock = ch.lock()) {
+		    logger.debug("Lock on {} acquired.", outpath);
 		    byte[] buffer = new byte[BUFFER_SIZE];
 		    int len;
 		    while ((len = inputStream.read(buffer)) > -1) {
 			out.write(buffer, 0, len);
 		    }
+		    logger.debug("Release lock on {}.", outpath);
 		}
 	    }
 	} else {
@@ -82,9 +93,12 @@ public void get(DsInfo dsInfo, Path path) throws IOException {
 	try (FileInputStream in = new FileInputStream(inpath)) {
 	    if (doFileLocking) {
 		FileChannel inch = in.getChannel();
+		logger.debug("Try to acquire a share lock on {}.", inpath);
 		try (FileLock lock = inch.lock(0L, Long.MAX_VALUE, true)) {
+		    logger.debug("Lock on {} acquired.", inpath);
 		    Files.copy(in, path, 
 			       StandardCopyOption.REPLACE_EXISTING);
+		    logger.debug("Release lock on {}.", inpath);
 		}
 	    } else {
 		Files.copy(in, path, 

src/main/java/org/icatproject/site/hzb/ids/storage/DirLock.java

@@ -13,6 +13,9 @@
 import java.util.EnumSet;
 import java.util.Set;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 
 /*********************************************************************
  *
@@ -26,6 +29,8 @@
 
 public class DirLock implements Closeable {
 
+    private static final Logger logger = LoggerFactory.getLogger(DirLock.class);
+
     private final static Set<PosixFilePermission> allrwPermissions 
 	    = PosixFilePermissions.fromString("rw-rw-rw-");
 
@@ -37,8 +42,11 @@ public class DirLock implements Closeable {
     private FileLock lock;
 
     private void acquireLock() throws IOException {
+	logger.debug("Try to acquire a {} lock on {}.",
+		     (shared ? "shared" : "exclusive"), dirname);
 	lf = new RandomAccessFile(lockf.toFile(), "rw");
 	lock = lf.getChannel().lock(0L, Long.MAX_VALUE, shared);
+	logger.debug("Lock on {} acquired.", dirname);
 	Files.setPosixFilePermissions(lockf, allrwPermissions);
     }
 
@@ -54,6 +62,7 @@ public DirLock(Path dir, boolean shared) throws IOException {
     }
 
     public void release() throws IOException {
+	logger.debug("Release lock on {}.", dirname);
 	lock.release();
 	lf.close();
     }

src/main/java/org/icatproject/site/hzb/ids/storage/MainFileStorage.java

@@ -19,12 +19,18 @@
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import org.icatproject.ids.plugin.AbstractMainStorage;
 import org.icatproject.ids.plugin.DsInfo;
 
 
 public class MainFileStorage extends AbstractMainStorage {
 
+    private static final Logger logger
+	= LoggerFactory.getLogger(MainFileStorage.class);
+
     public static final Pattern locationPrefixRegExp 
 	= Pattern.compile("([A-Za-z]+):([0-9A-Za-z./_~+-]+)");
 
@@ -56,6 +62,7 @@ public MainFileStorage(Properties properties) throws IOException {
 		extBaseDirs.put(extDir, props.getDirectory(propName));
 	    }
 	}
+	logger.info("MainFileStorage initialized");
     }
 
     /*
@@ -246,9 +253,12 @@ public List<DsInfo> getDatasetsToArchive(long lowArchivingLevel,
 
 	long size = treeSizeVisitor.getTotalSize();
 	if (size < highArchivingLevel) {
+	    logger.debug("Size {} < highArchivingLevel {} no action.",
+			 size, highArchivingLevel);
 	    return Collections.emptyList();
 	}
 	long recover = size - lowArchivingLevel;
+	logger.debug("Want to reduce size by {}.", recover);
 
 	List<DsInfo> result = new ArrayList<>();
 	for (DsInfoImpl dsInfo : treeSizeVisitor.getDsInfos()) {
@@ -258,6 +268,7 @@ public List<DsInfo> getDatasetsToArchive(long lowArchivingLevel,
 		break;
 	    }
 	}
+	logger.debug("{} DsInfos returned to reduce size", result.size());
 	return result;
     }