From b5c59b081c2781d3c6539ff30dba2e669094869a Mon Sep 17 00:00:00 2001
From: Timm Fitschen <timm.fitschen@ds.mpg.de>
Date: Wed, 10 Apr 2019 00:53:06 +0200
Subject: [PATCH] MAINT: update logging framew., add README_LOGGING.md

---
 .gitignore                                    |   2 +
 README_LOGGING.md                             |  62 +++++++++++
 conf/core/log4j2-debug.properties             |  17 +++
 conf/core/log4j2-default.properties           |  49 +++++++++
 conf/core/logging.conf                        |   5 -
 pom.xml                                       |  40 +++----
 .../java/caosdb/server/CaosAuthenticator.java |  10 +-
 src/main/java/caosdb/server/CaosDBServer.java | 100 ++++++++++--------
 .../accessControl/AuthenticationUtils.java    |  10 +-
 .../java/caosdb/server/accessControl/Pam.java |   8 +-
 .../server/accessControl/UserSources.java     |  15 ++-
 .../MySQL/DatabaseConnectionPool.java         |  64 +++++------
 .../caosdb/server/datatype/GenericValue.java  |   2 +-
 .../server/jobs/extension/AWIBoxLoan.java     |  59 ++++++-----
 .../server/logging/BackendLoggingHandler.java |  99 -----------------
 ...ssage.java => RequestErrorLogMessage.java} |   8 +-
 .../log4j/CustomConfigurationFactory.java     |  84 +++++++++++++++
 .../java/caosdb/datetime/DateTimeTest.java    |   5 +-
 .../caosdb/server/database/InsertTest.java    |  13 ++-
 .../caosdb/server/logging/TestLogging.java    |  57 ++++++++++
 .../caosdb/server/utils/FileUtilsTest.java    |   2 +-
 update_box_loan_acl.py                        |  37 -------
 22 files changed, 452 insertions(+), 296 deletions(-)
 create mode 100644 README_LOGGING.md
 create mode 100644 conf/core/log4j2-debug.properties
 create mode 100644 conf/core/log4j2-default.properties
 delete mode 100644 conf/core/logging.conf
 delete mode 100644 src/main/java/caosdb/server/logging/BackendLoggingHandler.java
 rename src/main/java/caosdb/server/logging/{RequestLogMessage.java => RequestErrorLogMessage.java} (94%)
 create mode 100644 src/main/java/caosdb/server/logging/log4j/CustomConfigurationFactory.java
 create mode 100644 src/test/java/caosdb/server/logging/TestLogging.java
 delete mode 100644 update_box_loan_acl.py

diff --git a/.gitignore b/.gitignore
index 92cf730f..3ef05150 100644
--- a/.gitignore
+++ b/.gitignore
@@ -21,7 +21,9 @@ target/
 
 # logfiles
 screen*log*
+log/
 
 # test files
 OUTBOX
 ConsistencyTest.xml
+testlog/
diff --git a/README_LOGGING.md b/README_LOGGING.md
new file mode 100644
index 00000000..e7b91bc7
--- /dev/null
+++ b/README_LOGGING.md
@@ -0,0 +1,62 @@
+# Logging
+
+## Framework
+
+We use the SLF4J API with a log4j2 backend for all of our Code. Please do not use log4j2 directly or any other logging API.
+
+Note that some libraries on the classpath use the `java.util.logging` API and log4j1 logging framework instead. These loggers cannot be configurated with the help of this README by now.
+
+## Configuration
+
+The configuration of the log4j2 backend is done via `properties` files which comply with the log4j2 specifications [1](https://logging.apache.org/log4j/2.x/manual/configuration.html#Properties). XML, YAML, or JSON files are not supported. The usual mechanisms for automatic configuratio with such files is disabled. Instead, files have to be placed into the `conf` subdirs, as follows:
+
+### Default and Debug Logging
+
+The default configuration is located at `conf/core/log4j2-default.properties`. For the debug mode, the configuration from `conf/core/log4j2-debug.properties` is merged with the default configuration. These files should not be changed by the user.
+
+### User Defined Logging
+
+The default and debug configuration can be overridden by the user with `conf/ext/log4j2.properties` and any file in the directory `conf/ext/log4j2.properties.d/` which is suffixed by `.properties`. All loggin configuration files are merged using the standard merge strategy of log4:
+
+> # Composite Configuration
+> Log4j allows multiple configuration files to be used by specifying them as a list of comma separated file paths on log4j.configurationFile. The merge logic can be controlled by specifying a class that implements the MergeStrategy interface on the log4j.mergeStrategy property. The default merge strategy will merge the files using the following rules:
+> 1. The global configuration attributes are aggregated with those in later configurations replacing those in previous configurations, with the exception that the highest status level and the lowest monitorInterval greater than 0 will be used.
+> 2. Properties from all configurations are aggregated. Duplicate properties replace those in previous configurations.
+> 3. Filters are aggregated under a CompositeFilter if more than one Filter is defined. Since Filters are not named duplicates may be present.
+> 4. Scripts and ScriptFile references are aggregated. Duplicate definiations replace those in previous configurations.
+> 5. Appenders are aggregated. Appenders with the same name are replaced by those in later configurations, including all of the Appender's subcomponents.
+> 6. Loggers are all aggregated. Logger attributes are individually merged with duplicates being replaced by those in later configurations. Appender references on a Logger are aggregated with duplicates being replaced by those in later configurations. Filters on a Logger are aggregated under a CompositeFilter if more than one Filter is defined. Since Filters are not named duplicates may be present. Filters under Appender references included or discarded depending on whether their parent Appender reference is kept or discarded.
+
+[2](https://logging.apache.org/log4j/2.x/manual/configuration.html#CompositeConfiguration)
+
+## Some Details and Examples
+
+### Make Verbose
+
+To make the server logs on the console more verbose, insert `rootLogger.level = DEBUG` or even `rootLogger.level = TRACE` into a properties file in the `conf/ext/log4j2.properties.d/` directory or the `conf/ext/log4j2.properties` file.
+
+### Log Directory
+
+By default, log files go to `./log/`, e.g. `./log/request_errors/current.log`. The log directory in `DEBUG_MODE` is located at `./testlog/`.
+
+To change that, insert `property.LOG_DIR = /path/to/my/logs` into a properties file in the `conf/ext/log4j2.properties.d/` directory or the `conf/ext/log4j2.properties` file
+
+### Special loggers
+
+* `REQUEST_ERRORS_LOGGER` for logging server errors with SRID, full request and full response. WARNING: This logger stores unencrypted content of request with possibly confidential content.
+* `REQUEST_TIME_LOGGER` for timing the requests.
+
+These loggers are defined in the `conf/core/log4j2-default.properties` file.
+
+#### Enable Request Time Logger
+
+The `REQUEST_TIME_LOGGER` is disabled by default, its log level is set to `OFF`. To enable it and write logs to the directory denoted by `property.LOG_DIR`, create a `properties` file under `conf/ext/log4j2.properties.d/` which contains at least
+
+```properties
+property.REQUEST_TIME_LOGGER_LEVEL = TRACE
+```
+
+### debug.log
+
+When in `DEBUG_MODE`, e.g. when started with `make run-debug`, the server also writes all logs to `debug.log` in the log directory.
+
diff --git a/conf/core/log4j2-debug.properties b/conf/core/log4j2-debug.properties
new file mode 100644
index 00000000..5d6b5fa1
--- /dev/null
+++ b/conf/core/log4j2-debug.properties
@@ -0,0 +1,17 @@
+# override location of log files for debugging and testing
+property.LOG_DIR = testlog
+
+# for unit testing
+logger.caosdb_server_logging.name = caosdb.server.logging
+logger.caosdb_server_logging.level = TRACE
+
+# ${LOG_DIR}/debug.log
+appender.debug.type = RandomAccessFile
+appender.debug.name = debug_log_file
+appender.debug.fileName = ${LOG_DIR}/debug.log
+appender.debug.layout.type = PatternLayout
+appender.debug.layout.pattern = [%d{HH:mm:ss:SSS}] [%p] [%c{1}:%L] - %m%n
+
+# append a debug.log file
+rootLogger.level = DEBUG
+rootLogger.appenderRef.tofile.ref = debug_log_file
\ No newline at end of file
diff --git a/conf/core/log4j2-default.properties b/conf/core/log4j2-default.properties
new file mode 100644
index 00000000..ab7aed26
--- /dev/null
+++ b/conf/core/log4j2-default.properties
@@ -0,0 +1,49 @@
+name = base_configuration
+status = TRACE
+verbose = true
+
+property.LOG_DIR = log
+property.REQUEST_TIME_LOGGER_LEVEL = OFF
+
+## appenders
+# stderr
+appender.stderr.type = Console
+appender.stderr.name = stderr
+appender.stderr.layout.type = PatternLayout
+appender.stderr.layout.pattern = [%d{yy-MMM-dd HH:mm:ss:SSS}] [%p] [%c{1}:%L] - %m%n
+appender.stderr.target = SYSTEM_ERR
+
+# ${LOG_DIR}/request_errors/...log
+appender.request_errors.type = RollingRandomAccessFile
+appender.request_errors.name = request_errors_log_file
+appender.request_errors.policy.type = TimeBasedTriggeringPolicy
+appender.request_errors.strategy.type = DefaultRolloverStrategy
+appender.request_errors.strategy.fileIndex = min
+appender.request_errors.strategy.max = 31
+appender.request_errors.fileName = ${LOG_DIR}/request_errors/current.log
+appender.request_errors.filePattern = ${LOG_DIR}/request_errors/%d{yyyy-MM-dd}.log
+appender.request_errors.filePermissions = rw-------
+appender.request_errors.layout.type = PatternLayout
+appender.request_errors.layout.pattern = TIME: %d{yy-MM-dd HH:mm:ss.SSS}%n%m%n%n%ex%n----------%n%n
+
+# ${LOG_DIR}/request_time.log
+appender.request_time.type = RandomAccessFile
+appender.request_time.name = request_time_log_file
+appender.request_time.fileName = ${LOG_DIR}/request_time.log
+appender.request_time.layout.type = PatternLayout
+appender.request_time.layout.pattern = [%d{yy-MM-dd HH:mm:ss.SSS}] - %m%n
+
+## loggers
+rootLogger.level = WARN
+rootLogger.appenderRef.stderr.ref = stderr
+
+logger.request_errors.additivity = false
+logger.request_errors.name = REQUEST_ERRORS_LOGGER
+logger.request_errors.appenderRef.tofile.ref = request_errors_log_file
+logger.request_errors.level = ERROR
+
+logger.request_time.additivity = false
+logger.request_time.name = REQUEST_TIME_LOGGER
+logger.request_time.appenderRef.tofile.ref = request_time_log_file
+logger.request_time.level = ${REQUEST_TIME_LOGGER_LEVEL}
+
diff --git a/conf/core/logging.conf b/conf/core/logging.conf
deleted file mode 100644
index c4ddcf78..00000000
--- a/conf/core/logging.conf
+++ /dev/null
@@ -1,5 +0,0 @@
-org.restlet.handlers = java.util.logging.ConsoleHandler
-caosdb.server.handlers = caosdb.server.logging.BackendLoggingHandler, java.util.logging.ConsoleHandler
-
-java.util.logging.ConsoleHandler.level = INFO
-caosdb.server.logging.BackendLogging.Handler.level = INFO
\ No newline at end of file
diff --git a/pom.xml b/pom.xml
index ef096967..d845abda 100644
--- a/pom.xml
+++ b/pom.xml
@@ -50,14 +50,14 @@
   </repositories>
   <dependencies>
     <dependency>
-      <groupId>org.slf4j</groupId>
-      <artifactId>slf4j-api</artifactId>
-      <version>1.8.0-beta2</version>
+      <groupId>org.apache.logging.log4j</groupId>
+      <artifactId>log4j-slf4j18-impl</artifactId>
+      <version>2.11.2</version>
     </dependency>
     <dependency>
       <groupId>org.slf4j</groupId>
-      <artifactId>slf4j-simple</artifactId>
-      <version>1.8.0-beta2</version>
+      <artifactId>slf4j-api</artifactId>
+      <version>1.8.0-beta4</version>
     </dependency>
     <dependency>
       <groupId>de.timmfitschen</groupId>
@@ -150,6 +150,16 @@
       <artifactId>jetty-util-ajax</artifactId>
       <version>9.2.14.v20151106</version>
     </dependency>
+    <dependency>
+      <groupId>org.apache.logging.log4j</groupId>
+      <artifactId>log4j-api</artifactId>
+      <version>2.11.2</version>
+    </dependency>
+    <dependency>
+      <groupId>org.apache.logging.log4j</groupId>
+      <artifactId>log4j-core</artifactId>
+      <version>2.11.2</version>
+    </dependency>
   </dependencies>
   <build>
     <sourceDirectory>${basedir}/src/main/java</sourceDirectory>
@@ -187,9 +197,6 @@
         <configuration>
           <descriptorRefs>
             <descriptorRef>jar-with-dependencies</descriptorRef>
-          
-            <!-- <descriptorRef>project</descriptorRef> -->
-            <!-- <descriptorRef>src</descriptorRef> -->
           </descriptorRefs>
           <archive>
             <manifest>
@@ -201,11 +208,15 @@
       <plugin>
         <groupId>org.apache.maven.plugins</groupId>
         <artifactId>maven-surefire-plugin</artifactId>
-        <version>2.22.0</version>
+        <version>3.0.0-M3</version>
         <configuration>
           <includes>
             <include>**/*.java</include>
           </includes>
+          <systemPropertyVariables>
+            <caosdb.debug>true</caosdb.debug>
+            <log4j2.debug>true</log4j2.debug>
+          </systemPropertyVariables>
         </configuration>
       </plugin>
       <plugin>
@@ -223,12 +234,6 @@
               <arguments>
                 <argument>silent</argument>
               </arguments>
-              <systemProperties>
-                <systemProperty>
-                  <key>java.util.loggin.config.file</key>
-                  <value>./conf/core/logging.conf</value>
-                </systemProperty>
-              </systemProperties>
             </configuration>
           </execution>
           <execution>
@@ -240,12 +245,11 @@
               <mainClass>caosdb.server.CaosDBServer</mainClass>
               <arguments>
                 <argument>silent</argument>
-                <argument>debug</argument>
               </arguments>
               <systemProperties>
                 <systemProperty>
-                  <key>java.util.loggin.config.file</key>
-                  <value>./conf/core/logging.conf</value>
+                  <key>caosdb.debug</key>
+                  <value>true</value>
                 </systemProperty>
               </systemProperties>
             </configuration>
diff --git a/src/main/java/caosdb/server/CaosAuthenticator.java b/src/main/java/caosdb/server/CaosAuthenticator.java
index 0cc6cc3d..25f112aa 100644
--- a/src/main/java/caosdb/server/CaosAuthenticator.java
+++ b/src/main/java/caosdb/server/CaosAuthenticator.java
@@ -26,8 +26,6 @@ import caosdb.server.accessControl.AuthenticationUtils;
 import caosdb.server.accessControl.OneTimeAuthenticationToken;
 import caosdb.server.accessControl.SessionToken;
 import caosdb.server.resource.DefaultResource;
-import java.util.logging.Level;
-import java.util.logging.Logger;
 import org.apache.shiro.SecurityUtils;
 import org.apache.shiro.authc.AuthenticationException;
 import org.apache.shiro.subject.Subject;
@@ -35,10 +33,12 @@ import org.restlet.Context;
 import org.restlet.Request;
 import org.restlet.Response;
 import org.restlet.security.Authenticator;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public class CaosAuthenticator extends Authenticator {
 
-  private static final Logger logger = Logger.getLogger(CaosAuthenticator.class.getName());
+  private static final Logger logger = LoggerFactory.getLogger(CaosAuthenticator.class.getName());
 
   public CaosAuthenticator(final Context context) {
     super(context);
@@ -61,7 +61,7 @@ public class CaosAuthenticator extends Authenticator {
         subject.login(sessionToken);
       }
     } catch (AuthenticationException e) {
-      logger.log(Level.INFO, "LOGIN_FAILED", e);
+      logger.info("LOGIN_FAILED", e);
     }
     // anonymous users
     if (!subject.isAuthenticated()
@@ -92,7 +92,7 @@ public class CaosAuthenticator extends Authenticator {
         subject.login(oneTimeToken);
       }
     } catch (final AuthenticationException e) {
-      logger.log(Level.INFO, "LOGIN_FAILED", e);
+      logger.info("LOGIN_FAILED", e);
     }
     return subject.isAuthenticated();
   }
diff --git a/src/main/java/caosdb/server/CaosDBServer.java b/src/main/java/caosdb/server/CaosDBServer.java
index 55232e2e..8a09ee18 100644
--- a/src/main/java/caosdb/server/CaosDBServer.java
+++ b/src/main/java/caosdb/server/CaosDBServer.java
@@ -35,8 +35,7 @@ import caosdb.server.datatype.AbstractDatatype;
 import caosdb.server.entity.EntityInterface;
 import caosdb.server.entity.Role;
 import caosdb.server.entity.container.Container;
-import caosdb.server.logging.BackendLoggingHandler;
-import caosdb.server.logging.RequestLogMessage;
+import caosdb.server.logging.RequestErrorLogMessage;
 import caosdb.server.resource.AuthenticationResource;
 import caosdb.server.resource.DefaultResource;
 import caosdb.server.resource.EntityOwnerResource;
@@ -65,9 +64,11 @@ import caosdb.server.utils.Initialization;
 import caosdb.server.utils.NullPrintStream;
 import caosdb.server.utils.Utils;
 import java.io.BufferedReader;
+import java.io.FileNotFoundException;
 import java.io.IOException;
 import java.io.InputStreamReader;
 import java.io.Reader;
+import java.time.ZoneId;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Properties;
@@ -75,7 +76,6 @@ import java.util.TimeZone;
 import java.util.logging.Handler;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
-import java.util.logging.Logger;
 import org.apache.shiro.SecurityUtils;
 import org.apache.shiro.config.Ini;
 import org.apache.shiro.config.Ini.Section;
@@ -104,11 +104,14 @@ import org.restlet.routing.Template;
 import org.restlet.routing.TemplateRoute;
 import org.restlet.routing.Variable;
 import org.restlet.util.Series;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public class CaosDBServer extends Application {
 
-  private static Logger logger = Logger.getLogger(CaosDBServer.class.getName());
+  private static Logger logger = LoggerFactory.getLogger(CaosDBServer.class);
   private static boolean DEBUG_MODE = false;
+  private static boolean START_GUI = true;
   private static Properties SERVER_PROPERTIES = null;
   private static Component component = null;
   private static ArrayList<Runnable> postShutdownHooks = new ArrayList<Runnable>();
@@ -121,7 +124,6 @@ public class CaosDBServer extends Application {
   }
 
   public static void initServerProperties() throws IOException {
-    logger.fine("read config files.");
     SERVER_PROPERTIES = ServerProperties.initServerProperties();
   }
 
@@ -147,7 +149,7 @@ public class CaosDBServer extends Application {
               + " from ServerProperty `"
               + ServerProperties.KEY_TIMEZONE
               + "`.");
-      TimeZone.setDefault(TimeZone.getTimeZone(serverProperty));
+      TimeZone.setDefault(TimeZone.getTimeZone(ZoneId.of(serverProperty)));
       logger.info("TIMEZONE = " + TimeZone.getDefault());
       return;
     }
@@ -155,7 +157,7 @@ public class CaosDBServer extends Application {
     String prop = System.getProperty("user.timezone");
     if (prop != null && !prop.isEmpty()) {
       logger.info("SET TIMEZONE = " + prop + " from JVM property `user.timezone`.");
-      TimeZone.setDefault(TimeZone.getTimeZone(prop));
+      TimeZone.setDefault(TimeZone.getTimeZone(ZoneId.of(prop)));
       logger.info("TIMEZONE = " + TimeZone.getDefault());
       return;
     }
@@ -163,7 +165,7 @@ public class CaosDBServer extends Application {
     String envVar = System.getenv("TZ");
     if (envVar != null && !envVar.isEmpty()) {
       logger.info("SET TIMEZONE = " + envVar + " from evironment variable `TZ`.");
-      TimeZone.setDefault(TimeZone.getTimeZone(envVar));
+      TimeZone.setDefault(TimeZone.getTimeZone(ZoneId.of(envVar)));
       logger.info("TIMEZONE = " + TimeZone.getDefault());
       return;
     }
@@ -171,22 +173,22 @@ public class CaosDBServer extends Application {
     String fromDate = getTimeZoneFromDate();
     if (fromDate != null && fromDate.isEmpty()) {
       logger.info("SET TIMEZONE = " + fromDate + " from `date +%Z`.");
-      TimeZone.setDefault(TimeZone.getTimeZone(fromDate));
+      TimeZone.setDefault(TimeZone.getTimeZone(ZoneId.of(fromDate)));
       logger.info("TIMEZONE = " + TimeZone.getDefault());
       return;
     }
 
-    logger.warning("COULD NOT SET TIMEZONE. DEFAULTS TO " + TimeZone.getDefault());
+    logger.warn("COULD NOT SET TIMEZONE. DEFAULTS TO " + TimeZone.getDefault());
   }
 
   public static String getTimeZoneFromDate() throws InterruptedException, IOException {
     final StringBuffer outputStringBuffer = new StringBuffer();
-    final Process cmd = Runtime.getRuntime().exec(new String[] {"date", "+%Z"});
+    final Process cmd = Runtime.getRuntime().exec(new String[] {"date", "+%z"});
     final int status = cmd.waitFor();
 
     if (status != 0) {
-      logger.warning(
-          "Could not determine time zone from `date +%Z`. The command returned with exit code "
+      logger.warn(
+          "Could not determine time zone from `date +%z`. The command returned with exit code "
               + cmd.exitValue());
       return null;
     }
@@ -200,7 +202,21 @@ public class CaosDBServer extends Application {
     if (outputStringBuffer.length() > 0) {
       return outputStringBuffer.toString().trim();
     } else {
-      throw new RuntimeException("Output of `date +%Z` command was empty.");
+      throw new RuntimeException("Output of `date +%z` command was empty.");
+    }
+  }
+
+  private static void init(final String[] args) {
+    for (final String s : args) {
+      if (s.equals("silent")) {
+        START_GUI = false;
+      } else if (s.equals("nobackend")) {
+        START_BACKEND = false;
+      } else if (s.equals("insecure")) {
+        INSECURE = true;
+      }
+
+      DEBUG_MODE = Boolean.getBoolean("caosdb.debug");
     }
   }
 
@@ -211,12 +227,15 @@ public class CaosDBServer extends Application {
    * @param args One option temporarily (for testing) available: silent: If present: disable
    *     System.out-stream (stream to a NullPrintStream). This makes the response of the database
    *     amazingly faster.
+   * @throws IOException
+   * @throws FileNotFoundException
+   * @throws SecurityException
    * @throws Exception If problems occur.
    */
-  public static void main(final String[] args) {
-    logger.fine("SERVER_START");
-
+  public static void main(final String[] args)
+      throws SecurityException, FileNotFoundException, IOException {
     try {
+      init(args);
       initServerProperties();
       initTimeZone();
     } catch (IOException | InterruptedException e1) {
@@ -224,19 +243,7 @@ public class CaosDBServer extends Application {
       System.err.println("Could not configure the server.");
       System.exit(1);
     }
-    boolean startGui = true;
 
-    for (final String s : args) {
-      if (s.equals("silent")) {
-        startGui = false;
-      } else if (s.equals("debug")) {
-        DEBUG_MODE = true;
-      } else if (s.equals("nobackend")) {
-        START_BACKEND = false;
-      } else if (s.equals("insecure")) {
-        INSECURE = true;
-      }
-    }
     INSECURE = INSECURE && DEBUG_MODE; // only allow insecure in debug mode
     START_BACKEND = START_BACKEND || !DEBUG_MODE; // always start backend if
     // not in debug mode
@@ -286,7 +293,7 @@ public class CaosDBServer extends Application {
       }
 
       // GUI
-      if (startGui) {
+      if (START_GUI) {
         final CaosDBTerminal caosDBTerminal = new CaosDBTerminal();
         caosDBTerminal.setName("CaosDBTerminal");
         caosDBTerminal.start();
@@ -321,7 +328,6 @@ public class CaosDBServer extends Application {
           Integer.parseInt(getServerProperty(ServerProperties.KEY_MAX_CONNECTIONS));
 
       init.release();
-      BackendLoggingHandler.start();
 
       if (INSECURE) {
         runHTTPServer(port_http, initialConnections, maxTotalConnections);
@@ -478,6 +484,9 @@ public class CaosDBServer extends Application {
     }
   }
 
+  public static final String REQUEST_TIME_LOGGER = "REQUEST_TIME_LOGGER";
+  public static final String REQUEST_ERRORS_LOGGER = "REQUEST_ERRORS_LOGGER";
+
   /**
    * Specify the dispatching restlet that maps URIs to their associated resources for processing.
    *
@@ -809,7 +818,10 @@ public class CaosDBServer extends Application {
 
 class CaosDBComponent extends Component {
 
-  private static Logger logger = Logger.getLogger(CaosDBComponent.class.getName());
+  private static Logger request_error_logger =
+      LoggerFactory.getLogger(CaosDBServer.REQUEST_ERRORS_LOGGER);
+  private static Logger request_time_logger =
+      LoggerFactory.getLogger(CaosDBServer.REQUEST_TIME_LOGGER);
 
   public CaosDBComponent() {
     super();
@@ -819,13 +831,14 @@ class CaosDBComponent extends Component {
 
   @Override
   public void handle(final Request request, final Response response) {
+    long t1 = System.currentTimeMillis();
     request.getAttributes().put("SRID", Utils.getUID());
     response.setServerInfo(CaosDBServer.getServerInfo());
     super.handle(request, response);
-    log(request, response);
+    log(request, response, t1);
   }
 
-  private void log(final Request request, final Response response) {
+  private void log(final Request request, final Response response, long t1) {
     if (response.getStatus() == Status.SERVER_ERROR_INTERNAL) {
       final Object object = request.getAttributes().get("THROWN");
       Throwable t = null;
@@ -833,16 +846,15 @@ class CaosDBComponent extends Component {
         t = (Throwable) object;
       }
 
-      final LogRecord rl =
-          new LogRecord(
-              Level.SEVERE, "ERROR:REQUEST:" + request.getAttributes().get("SRID").toString());
-      if (t != null) {
-        rl.setThrown(t);
-      }
-      final Object[] params = {new RequestLogMessage(request, response)};
-      rl.setParameters(params);
-      rl.setLoggerName(logger.getName());
-      logger.log(rl);
+      request_error_logger.error(
+          "SRID: {}\n{}",
+          request.getAttributes().get("SRID").toString(),
+          new RequestErrorLogMessage(request, response),
+          t);
     }
+    request_time_logger.trace(
+        "SRID: {} - Dur: {}",
+        request.getAttributes().get("SRID").toString(),
+        Long.toString(System.currentTimeMillis() - t1));
   }
 }
diff --git a/src/main/java/caosdb/server/accessControl/AuthenticationUtils.java b/src/main/java/caosdb/server/accessControl/AuthenticationUtils.java
index 31d180a4..6e0fd537 100644
--- a/src/main/java/caosdb/server/accessControl/AuthenticationUtils.java
+++ b/src/main/java/caosdb/server/accessControl/AuthenticationUtils.java
@@ -34,11 +34,11 @@ import caosdb.server.utils.Utils;
 import java.sql.Timestamp;
 import java.util.Collection;
 import java.util.LinkedList;
-import java.util.logging.Level;
-import java.util.logging.Logger;
 import org.apache.shiro.authc.AuthenticationToken;
 import org.restlet.data.Cookie;
 import org.restlet.data.CookieSetting;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * Useful static methods, mainly for parsing and serializing SessionTokens by the means of web
@@ -48,7 +48,7 @@ import org.restlet.data.CookieSetting;
  */
 public class AuthenticationUtils {
 
-  private static final Logger logger = Logger.getLogger(AuthenticationUtils.class.getName());
+  private static final Logger logger = LoggerFactory.getLogger(AuthenticationUtils.class);
 
   public static final String ONE_TIME_TOKEN_COOKIE = "OneTimeToken";
   public static final Message UNAUTHENTICATED =
@@ -110,7 +110,7 @@ public class AuthenticationUtils {
         try {
           return SessionToken.parse(tokenString, curry);
         } catch (final Exception e) {
-          logger.log(Level.WARNING, "AUTHTOKEN_PARSING_FAILED", e);
+          logger.warn("AUTHTOKEN_PARSING_FAILED", e);
         }
       }
     }
@@ -123,7 +123,7 @@ public class AuthenticationUtils {
       try {
         return OneTimeAuthenticationToken.parse(tokenString, curry);
       } catch (final Exception e) {
-        logger.log(Level.WARNING, "AUTHTOKEN_PARSING_FAILED", e);
+        logger.warn("AUTHTOKEN_PARSING_FAILED", e);
       }
     }
     return null;
diff --git a/src/main/java/caosdb/server/accessControl/Pam.java b/src/main/java/caosdb/server/accessControl/Pam.java
index d8eb41f0..c222fb83 100644
--- a/src/main/java/caosdb/server/accessControl/Pam.java
+++ b/src/main/java/caosdb/server/accessControl/Pam.java
@@ -35,10 +35,10 @@ import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
 public class Pam implements UserSource {
-	
+
   public static class DefaultPamScriptCaller implements PamScriptCaller {
-	  
-	  private Logger logger = LoggerFactory.getLogger(getClass());
+
+    private Logger logger = LoggerFactory.getLogger(getClass());
 
     private final String pam_script;
 
@@ -50,7 +50,7 @@ public class Pam implements UserSource {
     }
 
     public Process getProcess(final String username, final String password) throws IOException {
-    	
+
       final File script = new File(this.pam_script);
 
       final ProcessBuilder pb = new ProcessBuilder(script.getAbsolutePath(), username, password);
diff --git a/src/main/java/caosdb/server/accessControl/UserSources.java b/src/main/java/caosdb/server/accessControl/UserSources.java
index d96fdf14..2097478c 100644
--- a/src/main/java/caosdb/server/accessControl/UserSources.java
+++ b/src/main/java/caosdb/server/accessControl/UserSources.java
@@ -22,8 +22,6 @@
  */
 package caosdb.server.accessControl;
 
-import static java.util.logging.Level.SEVERE;
-
 import caosdb.server.CaosDBServer;
 import caosdb.server.ServerProperties;
 import caosdb.server.entity.Message;
@@ -36,17 +34,16 @@ import java.io.IOException;
 import java.util.HashMap;
 import java.util.HashSet;
 import java.util.Set;
-import java.util.logging.LogManager;
-import java.util.logging.Logger;
 import org.apache.shiro.authc.AuthenticationException;
 import org.apache.shiro.config.Ini;
 import org.apache.shiro.subject.PrincipalCollection;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public class UserSources extends HashMap<String, UserSource> {
 
   public static final String ANONYMOUS_ROLE = "anonymous";
-  private static final Logger logger =
-      LogManager.getLogManager().getLogger(UserSources.class.getName());
+  private static final Logger logger = LoggerFactory.getLogger(UserSources.class);
   public static final String KEY_DEAULT_REALM = "defaultRealm";
   public static final String KEY_REALMS = "defaultRealm";
   public static final String KEY_REALM_CLASS = "class";
@@ -77,11 +74,11 @@ public class UserSources extends HashMap<String, UserSource> {
                 (Class<? extends UserSource>) Class.forName(className);
             this.put(clazz.newInstance());
           } catch (final ClassNotFoundException e) {
-            logger.log(SEVERE, "LOAD_USER_SOURCE", e);
+            logger.error("LOAD_USER_SOURCE", e);
           } catch (final InstantiationException e) {
-            logger.log(SEVERE, "LOAD_USER_SOURCE", e);
+            logger.error("LOAD_USER_SOURCE", e);
           } catch (final IllegalAccessException e) {
-            logger.log(SEVERE, "LOAD_USER_SOURCE", e);
+            logger.error("LOAD_USER_SOURCE", e);
           }
         }
       }
diff --git a/src/main/java/caosdb/server/database/backend/implementation/MySQL/DatabaseConnectionPool.java b/src/main/java/caosdb/server/database/backend/implementation/MySQL/DatabaseConnectionPool.java
index d260aad1..9700daf3 100644
--- a/src/main/java/caosdb/server/database/backend/implementation/MySQL/DatabaseConnectionPool.java
+++ b/src/main/java/caosdb/server/database/backend/implementation/MySQL/DatabaseConnectionPool.java
@@ -32,42 +32,47 @@ import java.sql.PreparedStatement;
 import java.sql.ResultSet;
 import java.sql.SQLException;
 import java.sql.Statement;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import snaq.db.ConnectionPool;
 
 /**
- * DatabaseConnectionPool provides reuseable mysql Connections. They are configured and ready to
- * use.
+ * DatabaseConnectionPool provides reusable MySQL Connections. They are configured and ready to use.
+ *
+ * <p>Singleton
  *
  * @author Timm Fitschen
  */
 class DatabaseConnectionPool {
 
+  public static Logger logger = LoggerFactory.getLogger(DatabaseConnectionPool.class);
+
   static Connection getConnection() throws ConnectionException {
     try {
-      if (pool == null) {
-        pool = createConnectionPool();
+      if (instance == null) {
+        instance = createConnectionPool();
       }
-      Connection ret = pool.getConnection();
+      Connection ret = instance.getConnection();
       while (!ret.isValid(1000)) {
         ret.close();
-        ret = pool.getConnection();
+        ret = instance.getConnection();
       }
       ret.setReadOnly(true);
       ret.setAutoCommit(true);
       return ret;
     } catch (final Exception e) {
-      if (pool != null) {
-        pool.release();
+      if (instance != null) {
+        instance.release();
       }
-      pool = null;
+      instance = null;
       throw new ConnectionException(e);
     }
   }
 
-  /** Hidden Constructor. */
+  /** Singleton - Hidden Constructor. */
   private DatabaseConnectionPool() {}
 
-  private static ConnectionPool pool = null;
+  private static ConnectionPool instance = null;
 
   private static synchronized ConnectionPool createConnectionPool()
       throws ClassNotFoundException, InstantiationException, IllegalAccessException, SQLException,
@@ -103,10 +108,9 @@ class DatabaseConnectionPool {
               if (!pool.isReleased()) {
                 pool.releaseImmediately();
               }
-              System.err.print("Stopping MySQL connection pool [OK]\n");
+              logger.debug("Stopping MySQL connection pool [OK]\n");
             } catch (final Exception e) {
-              System.err.print("Stopping MySQL connection pool [failed]\n");
-              e.printStackTrace();
+              logger.error("Stopping MySQL connection pool [failed]\n", e);
             }
           }
         });
@@ -129,7 +133,7 @@ class DatabaseConnectionPool {
         p += query.getString(i);
         p += "|";
       }
-      System.err.println(p);
+      logger.debug(p);
     }
     query.close();
     statement.close();
@@ -143,7 +147,7 @@ class DatabaseConnectionPool {
         p += query.getString(i);
         p += "|";
       }
-      System.err.println(p);
+      logger.debug(p);
     }
     query.close();
     statement.close();
@@ -157,7 +161,7 @@ class DatabaseConnectionPool {
         p += query.getString(i);
         p += "|";
       }
-      System.err.println(p);
+      logger.debug(p);
     }
     query.close();
     statement.close();
@@ -165,11 +169,11 @@ class DatabaseConnectionPool {
   }
 
   static void printStatus() {
-    System.err.println("###### POOL ########");
-    System.err.println("#free   : " + pool.getFreeCount());
-    System.err.println("#checked: " + pool.getCheckedOut());
-    System.err.println("#params : " + pool.getParametersString());
-    System.err.println("####################");
+    logger.debug("###### POOL ########");
+    logger.debug("#free   : " + instance.getFreeCount());
+    logger.debug("#checked: " + instance.getCheckedOut());
+    logger.debug("#params : " + instance.getParametersString());
+    logger.debug("####################");
   }
 
   private static void checkVersion(final Connection con)
@@ -185,18 +189,15 @@ class DatabaseConnectionPool {
                   .toLowerCase();
           final String v_a = executeQuery.getString(1).toLowerCase();
           if (!Objects.equal(v_a, v_e)) {
-            System.err.println(
-                "Version of the MySQL schema is wrong.\n\tExpected: "
-                    + v_e
-                    + "\n\tActual: "
-                    + v_a
-                    + "\n\n ----> Please execute the bash script '../db_creation/patches/applyPatches' or reinstall the database schema.\n\n");
+            logger.error(
+                "Version of the MySQL schema is wrong.\n\tExpected: {}\n\tActual: {}n\nPlease upgrade the mysql backend.\n\n",
+                v_e,
+                v_a);
             System.exit(1);
           }
         }
       } catch (final SQLException e) {
-        e.printStackTrace();
-        System.err.println("Could not check the version of the MySQL schema.");
+        logger.error("Could not check the version of the MySQL schema.", e);
         System.exit(1);
       }
 
@@ -211,8 +212,7 @@ class DatabaseConnectionPool {
       try {
         prepareCall.execute();
       } catch (final SQLException e) {
-        e.printStackTrace();
-        System.err.println("Could inititialize the autoincrement value for the entities table.");
+        logger.error("Could inititialize the autoincrement value for the entities table.", e);
         System.exit(1);
       }
     } finally {
diff --git a/src/main/java/caosdb/server/datatype/GenericValue.java b/src/main/java/caosdb/server/datatype/GenericValue.java
index 8bb79af1..d6140ff7 100644
--- a/src/main/java/caosdb/server/datatype/GenericValue.java
+++ b/src/main/java/caosdb/server/datatype/GenericValue.java
@@ -77,7 +77,7 @@ public class GenericValue implements SingleValue {
 
   @Override
   public String toString() {
-    throw new NullPointerException("toString Method!!!");
+    return toDatabaseString();
   }
 
   @Override
diff --git a/src/main/java/caosdb/server/jobs/extension/AWIBoxLoan.java b/src/main/java/caosdb/server/jobs/extension/AWIBoxLoan.java
index 684a6f40..65c96896 100644
--- a/src/main/java/caosdb/server/jobs/extension/AWIBoxLoan.java
+++ b/src/main/java/caosdb/server/jobs/extension/AWIBoxLoan.java
@@ -27,10 +27,13 @@ import caosdb.server.utils.Utils;
 import java.util.Iterator;
 import java.util.List;
 import java.util.Objects;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 @JobAnnotation(transaction = caosdb.server.transaction.WriteTransaction.class, loadAlways = true)
 public class AWIBoxLoan extends AWIBoxLoanModel {
 
+  public Logger logger = LoggerFactory.getLogger(getClass());
   private static final Message UNIQUE_USER =
       new Message("The user must have a unique combination of first name and last name!");
   private static final Message BOX_HAS_LOAN =
@@ -105,14 +108,14 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
   boolean isManualReturnUpdateLoan() {
     for (EntityInterface e : getContainer()) {
       if (!isLoanRecord(e) || !hasManualReturnLoanProperties(e)) {
-        System.err.println("### isManualReturnUpdateLoan: false");
+        logger.trace("isManualReturnUpdateLoan: false");
         return false;
       }
     }
     for (EntityInterface e : getContainer()) {
       removeAnonymousPermissions(e);
     }
-    System.err.println("### isManualReturnUpdateLoan: true");
+    logger.trace("isManualReturnUpdateLoan: true");
     return true;
   }
 
@@ -139,11 +142,11 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
   boolean isManualReturnUpdateBox() {
     for (EntityInterface e : getContainer()) {
       if (!isBoxRecord(e) || !hasManualReturnBoxProperties(e)) {
-        System.err.println("### isManualReturnUpdateBox: false");
+        logger.trace("isManualReturnUpdateBox: false");
         return false;
       }
     }
-    System.err.println("### isManualReturnUpdateBox: true");
+    logger.trace("isManualReturnUpdateBox: true");
     return true;
   }
 
@@ -187,14 +190,14 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
   private boolean isRejectReturnUpdateLoan() {
     for (EntityInterface e : getContainer()) {
       if (!isLoanRecord(e) || !hasRejectReturnProperties(e)) {
-        System.err.println("### isRejectReturnUpdateLoan: false");
+        logger.trace("isRejectReturnUpdateLoan: false");
         return false;
       }
     }
     for (EntityInterface e : getContainer()) {
       removeDestinationProperty(e);
     }
-    System.err.println("### isRejectReturnUpdateLoan: true");
+    logger.trace("isRejectReturnUpdateLoan: true");
     return true;
   }
 
@@ -214,11 +217,11 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
       if (isDestinationProperty(p)) {
         found = true;
       } else if (isReturnAcceptedProperty(p) || isReturnRequestProperty(p)) {
-        System.err.println("### hasRejectReturnProperties: false");
+        logger.trace("hasRejectReturnProperties: false");
         return false;
       }
     }
-    System.err.println("### hasRejectReturnProperties found: " + found);
+    logger.trace("hasRejectReturnProperties found: {}", found);
     return found;
   }
 
@@ -229,11 +232,11 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
   boolean isAcceptReturnUpdateLoan() {
     for (EntityInterface e : getContainer()) {
       if (!isLoanRecord(e) || !hasAcceptReturnProperties(e)) {
-        System.err.println("### isAcceptReturnUpdateLoan: false");
+        logger.trace("isAcceptReturnUpdateLoan: false");
         return false;
       }
     }
-    System.err.println("### isAcceptReturnUpdateLoan: true");
+    logger.trace("isAcceptReturnUpdateLoan: true");
     return true;
   }
 
@@ -250,7 +253,7 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
   boolean isConfirmLoanUpdateLoan() {
     for (EntityInterface e : getContainer()) {
       if (!isLoanRecord(e) || !hasConfirmLoanProperties(e)) {
-        System.err.println("### isConfirmLoanUpdateLoan: false");
+        logger.trace("isConfirmLoanUpdateLoan: false");
         return false;
       }
     }
@@ -258,7 +261,7 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
     for (EntityInterface e : getContainer()) {
       switchDestinationToLocation(e);
     }
-    System.err.println("### isConfirmLoanUpdateLoan: true");
+    logger.trace("isConfirmLoanUpdateLoan: true");
     return true;
   }
 
@@ -282,22 +285,22 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
       if (isLentProperty(p)) {
         found = true;
       } else if (isReturnAcceptedProperty(p) || isDestinationProperty(p)) {
-        System.err.println("### hasConfirmLoanProperties: false");
+        logger.trace("hasConfirmLoanProperties: false");
         return false;
       }
     }
-    System.err.println("### hasConfirmLoanProperties found: " + found);
+    logger.trace("hasConfirmLoanProperties found: {}", found);
     return found;
   }
 
   boolean isAcceptBorrowUpdateLoan() {
     for (EntityInterface e : getContainer()) {
       if (!isLoanRecord(e) || !hasLoanAcceptProperties(e)) {
-        System.err.println("### isAcceptBorrowUpdateLoan: false");
+        logger.trace("isAcceptBorrowUpdateLoan: false");
         return false;
       }
     }
-    System.err.println("### isAcceptBorrowUpdateLoan: true");
+    logger.trace("isAcceptBorrowUpdateLoan: true");
     return true;
   }
 
@@ -307,11 +310,11 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
       if (isLoanAcceptProperty(p)) {
         found = true;
       } else if (isLentProperty(p) || isReturnAcceptedProperty(p)) {
-        System.err.println("### hasLoanAcceptProperties: false");
+        logger.trace("hasLoanAcceptProperties: false");
         return false;
       }
     }
-    System.err.println("### hasLoanAcceptProperties found: " + found);
+    logger.trace("hasLoanAcceptProperties found: {}", found);
     return found;
   }
 
@@ -348,7 +351,7 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
 
   boolean isAnonymous() {
     boolean ret = getUser().hasRole(UserSources.ANONYMOUS_ROLE);
-    System.err.print("### is Anonymous: " + ret);
+    logger.trace("is Anonymous: {}", ret);
     return ret;
   }
 
@@ -358,22 +361,22 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
       // Container has only loan elements with special properties
       for (EntityInterface e : getContainer()) {
         if (!isLoanRecord(e) || !hasOnlyAllowedLoanProperties4RequestReturn(e)) {
-          System.err.println("### isRequestReturnUpdateLoan: false");
+          logger.trace("isRequestReturnUpdateLoan: false");
           return false;
         }
         setReturnRequestedDate(e);
       }
       appendJob(AWIBoxLoanRequestReturnCuratorEmail.class);
-      System.err.println("### isRequestReturnUpdateLoan: true");
+      logger.trace("isRequestReturnUpdateLoan: true");
       return true;
     }
-    System.err.println("### isRequestReturnUpdateLoan: false");
+    logger.trace("isRequestReturnUpdateLoan: false");
     return false;
   }
 
   boolean isRequestReturnSetUser() {
     // same as request_loan.set_user
-    System.err.println("### isRequestReturnSetUser: ->");
+    logger.trace("isRequestReturnSetUser: ->");
     return isRequestLoanSetUser();
   }
 
@@ -455,6 +458,7 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
   }
 
   private void setDateProperty(EntityInterface e, Integer propertyId) {
+    // TODO
     EntityInterface p = retrieveValidEntity(propertyId);
     p.setValue(getTransaction().getTimestamp());
     e.addProperty(new Property(p));
@@ -474,10 +478,10 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
         && checkEmail(getContainer().get(0))) {
       appendJob(getContainer().get(0), CheckNoAdditionalPropertiesPresent.class);
       appendJob(getContainer().get(0), CheckNoOverridesPresent.class);
-      System.err.println("### isRequestReturnSetUser: true");
+      logger.trace("isRequestReturnSetUser: true");
       return true;
     }
-    System.err.println("### isRequestReturnSetUser: false");
+    logger.trace("isRequestReturnSetUser: false");
     return false;
   }
 
@@ -540,13 +544,12 @@ public class AWIBoxLoan extends AWIBoxLoanModel {
         if (isReturnRequestProperty(p)) {
           foundReturnRequested = true;
         } else if (isReturnAcceptedProperty(p) || isReturnedProperty(p)) {
-          System.err.println("### hasOnlyAllowedLoanProperties4RequestReturn: false");
+          logger.trace("hasOnlyAllowedLoanProperties4RequestReturn: false");
           return false; // this is not a returnRequest, return has already been accepted
         }
       }
     }
-    System.err.println(
-        "### hasOnlyAllowedLoanProperties4RequestReturn found: " + foundReturnRequested);
+    logger.trace("hasOnlyAllowedLoanProperties4RequestReturn found: {}", foundReturnRequested);
     return foundReturnRequested;
   }
 
diff --git a/src/main/java/caosdb/server/logging/BackendLoggingHandler.java b/src/main/java/caosdb/server/logging/BackendLoggingHandler.java
deleted file mode 100644
index 62fe6948..00000000
--- a/src/main/java/caosdb/server/logging/BackendLoggingHandler.java
+++ /dev/null
@@ -1,99 +0,0 @@
-/*
- * ** header v3.0
- * This file is a part of the CaosDB Project.
- *
- * Copyright (C) 2018 Research Group Biomedical Physics,
- * Max-Planck-Institute for Dynamics and Self-Organization Göttingen
- *
- * This program is free software: you can redistribute it and/or modify
- * it under the terms of the GNU Affero General Public License as
- * published by the Free Software Foundation, either version 3 of the
- * License, or (at your option) any later version.
- *
- * This program is distributed in the hope that it will be useful,
- * but WITHOUT ANY WARRANTY; without even the implied warranty of
- * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
- * GNU Affero General Public License for more details.
- *
- * You should have received a copy of the GNU Affero General Public License
- * along with this program. If not, see <https://www.gnu.org/licenses/>.
- *
- * ** end header
- */
-package caosdb.server.logging;
-
-import caosdb.server.transaction.InsertLogRecordTransaction;
-import caosdb.server.utils.CronJob;
-import java.util.LinkedList;
-import java.util.List;
-import java.util.logging.ErrorManager;
-import java.util.logging.Handler;
-import java.util.logging.LogRecord;
-
-public class BackendLoggingHandler extends Handler {
-
-  private static List<LogRecord> list = new LinkedList<LogRecord>();
-  private static final Integer lock = 0;
-  private static boolean isConnected = false;
-
-  private static void setIsConnected(final boolean b) {
-    isConnected = b;
-  }
-
-  @Override
-  public void close() throws SecurityException {
-    flush();
-    setIsConnected(false);
-  }
-
-  @Override
-  public void flush() {
-    doFlush(getErrorManager());
-  }
-
-  private static void doFlush(final ErrorManager em) {
-    List<LogRecord> toBeFlushed = null;
-    synchronized (lock) {
-      if (!isConnected) {
-        return;
-      }
-      if (list.isEmpty()) {
-        return;
-      } else {
-        toBeFlushed = list;
-        list = new LinkedList<LogRecord>();
-      }
-    }
-    writeToBackend(toBeFlushed, em);
-  }
-
-  private static void writeToBackend(final List<LogRecord> toBeFlushed, final ErrorManager em) {
-    final InsertLogRecordTransaction t = new InsertLogRecordTransaction(toBeFlushed);
-    try {
-      t.execute();
-    } catch (final Exception e) {
-      em.error("Flushing LogRecords failed", e, 0);
-    }
-  }
-
-  @Override
-  public void publish(final LogRecord arg0) {
-    synchronized (lock) {
-      list.add(arg0);
-    }
-  }
-
-  public static void start() {
-    setIsConnected(true);
-    new CronJob(
-        "FLUSH SERVER LOGS",
-        new Runnable() {
-
-          @Override
-          public void run() {
-            doFlush(new ErrorManager());
-          }
-        },
-        10);
-  }
-}
diff --git a/src/main/java/caosdb/server/logging/RequestLogMessage.java b/src/main/java/caosdb/server/logging/RequestErrorLogMessage.java
similarity index 94%
rename from src/main/java/caosdb/server/logging/RequestLogMessage.java
rename to src/main/java/caosdb/server/logging/RequestErrorLogMessage.java
index 1b0fdef3..ddffe7d5 100644
--- a/src/main/java/caosdb/server/logging/RequestLogMessage.java
+++ b/src/main/java/caosdb/server/logging/RequestErrorLogMessage.java
@@ -34,7 +34,7 @@ import org.restlet.engine.header.HeaderConstants;
 import org.restlet.representation.Representation;
 import org.restlet.util.Series;
 
-public class RequestLogMessage implements Serializable {
+public class RequestErrorLogMessage implements Serializable {
 
   /** */
   private static final long serialVersionUID = 4683559833384175003L;
@@ -46,9 +46,9 @@ public class RequestLogMessage implements Serializable {
   public String request_entity = null;
   public String response_entity = null;
 
-  public RequestLogMessage() {}
+  public RequestErrorLogMessage() {}
 
-  public RequestLogMessage(final Request request, final Response response) {
+  public RequestErrorLogMessage(final Request request, final Response response) {
     if (request != null) {
       this.request = request.toString();
       this.request_headers = getHeaders(request);
@@ -100,7 +100,7 @@ public class RequestLogMessage implements Serializable {
   public String toString() {
     final StringBuilder sb = new StringBuilder();
 
-    sb.append("\nREQUEST: ");
+    sb.append("REQUEST: ");
     sb.append(this.request);
     if (this.request_headers != null) {
       sb.append("\nREQUEST HEADERS: ");
diff --git a/src/main/java/caosdb/server/logging/log4j/CustomConfigurationFactory.java b/src/main/java/caosdb/server/logging/log4j/CustomConfigurationFactory.java
new file mode 100644
index 00000000..0972e1d8
--- /dev/null
+++ b/src/main/java/caosdb/server/logging/log4j/CustomConfigurationFactory.java
@@ -0,0 +1,84 @@
+package caosdb.server.logging.log4j;
+
+import com.google.common.io.PatternFilenameFilter;
+import java.io.File;
+import java.net.URI;
+import java.util.ArrayList;
+import java.util.Arrays;
+import java.util.Comparator;
+import java.util.List;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.config.AbstractConfiguration;
+import org.apache.logging.log4j.core.config.Configuration;
+import org.apache.logging.log4j.core.config.ConfigurationFactory;
+import org.apache.logging.log4j.core.config.ConfigurationSource;
+import org.apache.logging.log4j.core.config.Order;
+import org.apache.logging.log4j.core.config.composite.CompositeConfiguration;
+import org.apache.logging.log4j.core.config.plugins.Plugin;
+import org.apache.logging.log4j.core.config.properties.PropertiesConfigurationFactory;
+import org.apache.logging.log4j.core.util.NetUtils;
+
+@Plugin(name = "CustomConfigurationFactory", category = ConfigurationFactory.CATEGORY)
+@Order(100)
+public class CustomConfigurationFactory extends PropertiesConfigurationFactory {
+
+  private File core_default = new File("conf/core/log4j2-default.properties");
+  private File core_debug = new File("conf/core/log4j2-debug.properties");
+  private File ext_file = new File("conf/ext/log4j2.properties");
+  private File ext_dir = new File("conf/ext/log4j2.properties.d");
+
+  private List<String> getConfigFiles() {
+    List<String> configFiles = new ArrayList<>(10);
+    configFiles.add(core_default.getAbsolutePath());
+    if (Boolean.getBoolean("caosdb.debug")) {
+      configFiles.add(core_debug.getAbsolutePath());
+    }
+    if (ext_file.exists()) {
+      configFiles.add(ext_file.getAbsolutePath());
+    }
+    if (ext_dir.exists() && ext_dir.isDirectory()) {
+      String[] confFiles = ext_dir.list(new PatternFilenameFilter("\\.properties$"));
+      Arrays.sort(confFiles, Comparator.naturalOrder());
+      for (String fileName : confFiles) {
+        configFiles.add(ext_dir.toPath().toAbsolutePath().resolve(fileName).toString());
+      }
+    }
+    return configFiles;
+  }
+
+  @Override
+  public Configuration getConfiguration(
+      LoggerContext loggerContext, String name, URI configLocation) {
+    LOGGER.debug("Reconfiguration is done by {}", getClass().toString());
+
+    List<String> sources = getConfigFiles();
+    if (sources.size() > 1) {
+      final List<AbstractConfiguration> configs = new ArrayList<>();
+      for (final String sourceLocation : sources) {
+        LOGGER.debug("Reconfigure with {}", sourceLocation);
+        ConfigurationSource source = null;
+        try {
+          source = ConfigurationSource.fromUri(NetUtils.toURI(sourceLocation));
+        } catch (final Exception ex) {
+          // Ignore the error and try as a String.
+          LOGGER.catching(Level.DEBUG, ex);
+        }
+        final Configuration config = super.getConfiguration(loggerContext, source);
+        if (config != null && config instanceof AbstractConfiguration) {
+          configs.add((AbstractConfiguration) config);
+        } else {
+          LOGGER.error("Failed to created configuration at {}", sourceLocation);
+          return null;
+        }
+      }
+      return new CompositeConfiguration(configs);
+    }
+    return super.getConfiguration(loggerContext, name, configLocation);
+  }
+
+  @Override
+  protected String[] getSupportedTypes() {
+    return new String[] {"*"};
+  }
+}
diff --git a/src/test/java/caosdb/datetime/DateTimeTest.java b/src/test/java/caosdb/datetime/DateTimeTest.java
index b2bbc5fc..cb24d3bd 100644
--- a/src/test/java/caosdb/datetime/DateTimeTest.java
+++ b/src/test/java/caosdb/datetime/DateTimeTest.java
@@ -31,7 +31,7 @@ import caosdb.server.database.backend.implementation.MySQL.ConnectionException;
 import java.io.IOException;
 import java.sql.SQLException;
 import java.sql.Timestamp;
-import java.util.Arrays;
+import java.time.ZoneId;
 import java.util.GregorianCalendar;
 import java.util.TimeZone;
 import org.junit.Assert;
@@ -49,7 +49,8 @@ public class DateTimeTest {
   @Test
   public void testGetTimeZoneFromDate() throws InterruptedException, IOException {
     String tz = CaosDBServer.getTimeZoneFromDate();
-    Assert.assertTrue(Arrays.asList(TimeZone.getAvailableIDs()).contains(tz));
+    ZoneId of = java.time.ZoneId.of(tz);
+    Assert.assertNotNull(of);
   }
 
   @Test
diff --git a/src/test/java/caosdb/server/database/InsertTest.java b/src/test/java/caosdb/server/database/InsertTest.java
index 470c99af..70fef365 100644
--- a/src/test/java/caosdb/server/database/InsertTest.java
+++ b/src/test/java/caosdb/server/database/InsertTest.java
@@ -119,8 +119,6 @@ public class InsertTest {
     p10.setStatementStatus(StatementStatus.OBLIGATORY);
     p9.addProperty(p10);
 
-    // r.print();
-
     final LinkedList<EntityInterface> stage1Inserts = new LinkedList<EntityInterface>();
     final LinkedList<EntityInterface> stage2Inserts = new LinkedList<EntityInterface>();
     new LinkedList<EntityInterface>();
@@ -226,6 +224,8 @@ public class InsertTest {
     subp.setStatementStatus(StatementStatus.FIX);
     p2.addProperty(subp);
 
+    r.print();
+
     final LinkedList<EntityInterface> stage1Inserts = new LinkedList<EntityInterface>();
     final LinkedList<EntityInterface> stage2Inserts = new LinkedList<EntityInterface>();
 
@@ -254,6 +254,15 @@ public class InsertTest {
     assertEquals((Integer) 2, stage2Inserts.get(0).getId());
     assertEquals("V2", ((SingleValue) stage2Inserts.get(0).getValue()).toDatabaseString());
     assertFalse(stage2Inserts.get(0).hasReplacement());
+
+    System.out.println("######### stage 1 #########");
+    for (EntityInterface e : stage1Inserts) {
+      e.print();
+    }
+    System.out.println("######### stage 2 #########");
+    for (EntityInterface e : stage2Inserts) {
+      e.print();
+    }
   }
 
   /**
diff --git a/src/test/java/caosdb/server/logging/TestLogging.java b/src/test/java/caosdb/server/logging/TestLogging.java
new file mode 100644
index 00000000..73d62401
--- /dev/null
+++ b/src/test/java/caosdb/server/logging/TestLogging.java
@@ -0,0 +1,57 @@
+package caosdb.server.logging;
+
+import caosdb.server.CaosDBServer;
+import java.io.File;
+import java.io.IOException;
+import org.apache.commons.io.FileUtils;
+import org.junit.Assert;
+import org.junit.BeforeClass;
+import org.junit.Test;
+import org.restlet.Request;
+import org.restlet.Response;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public class TestLogging {
+
+  private Logger logger = LoggerFactory.getLogger(getClass());
+  private Logger request_errors_logger =
+      LoggerFactory.getLogger(CaosDBServer.REQUEST_ERRORS_LOGGER);
+  private Logger request_time_logger = LoggerFactory.getLogger(CaosDBServer.REQUEST_TIME_LOGGER);
+
+  @BeforeClass
+  public static void setup() throws IOException {
+    File f = new File("testlog/");
+    FileUtils.forceDeleteOnExit(f);
+  }
+
+  @Test
+  public void testLogger() {
+    logger.error("error");
+    logger.warn("warn");
+    logger.info("info");
+    logger.debug("debug");
+    logger.trace("trace");
+    Assert.assertEquals(logger.getName(), "caosdb.server.logging.TestLogging");
+    Assert.assertTrue(logger.isErrorEnabled());
+    Assert.assertTrue(logger.isWarnEnabled());
+    Assert.assertTrue(logger.isInfoEnabled());
+    Assert.assertTrue(logger.isDebugEnabled());
+    Assert.assertTrue(logger.isTraceEnabled());
+  }
+
+  @Test
+  public void testRequestErrorsLogger() {
+    Assert.assertTrue(request_errors_logger.isErrorEnabled());
+    request_errors_logger.error(
+        "ERROR:REQUEST:" + "ABC0123",
+        new RequestErrorLogMessage(new Request(), new Response(null)),
+        new Exception("exc"));
+  }
+
+  @Test
+  public void testRequestTimeLogger() {
+    Assert.assertTrue(request_time_logger.isDebugEnabled());
+    request_time_logger.debug("test");
+  }
+}
diff --git a/src/test/java/caosdb/server/utils/FileUtilsTest.java b/src/test/java/caosdb/server/utils/FileUtilsTest.java
index 4d5262fc..bec2e3fa 100644
--- a/src/test/java/caosdb/server/utils/FileUtilsTest.java
+++ b/src/test/java/caosdb/server/utils/FileUtilsTest.java
@@ -242,7 +242,7 @@ public class FileUtilsTest {
 
   @Test
   public void testCreateFolders() throws Message {
-    final File f = new File("testfolder/testsubfolder/testfile");
+    final File f = new File(testRoot.getAbsoluteFile() + "/testfolder/testsubfolder/testfile");
     Assert.assertFalse(f.getAbsoluteFile().getParentFile().exists());
     final Undoable u = FileUtils.createFolders(f.getAbsoluteFile().getParentFile());
     Assert.assertTrue(f.getAbsoluteFile().getParentFile().exists());
diff --git a/update_box_loan_acl.py b/update_box_loan_acl.py
deleted file mode 100644
index c49dd01e..00000000
--- a/update_box_loan_acl.py
+++ /dev/null
@@ -1,37 +0,0 @@
-#!/usr/bin/env python3
-
-import sys
-import caosdb as db
-
-boxes = db.execute_query("FIND RECORD Box")
-persons = db.execute_query("FIND RECORD Person")
-loans = db.execute_query("FIND RECORD LOAN")
-
-num = len(boxes) + len(persons) + len(loans)
-i = 0
-
-def progress():
-    global i
-    i += 1
-    sys.stdout.write("\rprocessing {i}/{num} entities, {perc}%".format(i=i,num=num, perc=float(100*i)/float(num)))
-    sys.stdout.flush()
-
-for Box in boxes:
-    progress()
-    box.retrieve_acl()
-    box.grant(role="anonymous", permissions="UPDATE:PROPERTY:ADD")
-    box.update_acl()
-
-for person in persons:
-    progress()
-    person.retrieve_acl()
-    person.grant(role="anonymous", permissions="UPDATE:PROPERTY:ADD")
-    person.grant(role="anonymous", permissions="UPDATE:PROPERTY:REMOVE")
-    person.update_acl()
-
-for loan in loans:
-    progress()
-    loan.retrieve_acl()
-    loan.grant(role="anonymous", permissions="UPDATE:PROPERTY:ADD")
-    loan.grant(role="anonymous", permissions="UPDATE:PROPERTY:REMOVE")
-    loan.update_acl()
-- 
GitLab