Add another logging destination (#1847)

- introduces logging of ETL to a separate file
- separates external libs logs into dedicated log file
- change log pattern to be more concise

pom.xml

@@ -164,6 +164,16 @@
 			<artifactId>jaxb-api</artifactId>
 			<version>2.3.0</version>
 		</dependency>
+		<dependency>
+			<groupId>ch.qos.logback</groupId>
+			<artifactId>logback-classic</artifactId>
+			<version>1.3.11</version>
+		</dependency>
+		<dependency>
+			<groupId>ch.qos.logback</groupId>
+			<artifactId>logback-core</artifactId>
+			<version>1.3.11</version>
+		</dependency>
 	</dependencies>
 	<build>
 		<resources>

src/main/java/de/hbz/lobid/helper/CompareJsonMaps.java

@@ -33,7 +33,7 @@
  */
 @SuppressWarnings("javadoc")
 public final class CompareJsonMaps {
-	final static Logger logger = LoggerFactory.getLogger(CompareJsonMaps.class);
+	final static Logger logger = LoggerFactory.getLogger("etl");
 	Stack<String> stack = new Stack<>();
 	static final String JSON_LD_CONTEXT = "[@context";
 	private static boolean IGNORE_CONTEXT = true;

src/main/java/de/hbz/lobid/helper/Etikett.java

@@ -24,7 +24,7 @@
  */
 @XmlRootElement
 public class Etikett {
-	final static Logger logger = LoggerFactory.getLogger(Etikett.class);
+	final static Logger logger = LoggerFactory.getLogger("etl");
 
 	public enum EtikettType {
 		CACHE, CONTEXT, STORE

src/main/java/de/hbz/lobid/helper/EtikettMaker.java

@@ -29,7 +29,7 @@ public class EtikettMaker implements EtikettMakerInterface {
     private static final String ID = "id";
     private String contextLocation = "web/conf/context.jsonld";
 
-    final static Logger logger = LoggerFactory.getLogger(EtikettMaker.class);
+    final static Logger logger = LoggerFactory.getLogger("etl");
 
     /**
      * A map with URIs as key

src/main/java/de/hbz/lobid/helper/HttpPoster.java

@@ -21,7 +21,7 @@ public final class HttpPoster {
     public final String POST = "POST";
     private String contentType = "application/json";
     private URL url;
-    private static final Logger LOG = LoggerFactory.getLogger(HttpPoster.class);
+    private static final Logger LOG = LoggerFactory.getLogger("etl");
 
     /**
      * Creates an instance of {@link HttpPoster}.

src/main/java/org/lobid/resources/ElasticsearchIndexer.java

@@ -64,7 +64,7 @@
 public class ElasticsearchIndexer
 		extends DefaultObjectPipe<HashMap<String, String>, ObjectReceiver<Void>> {
 
-	private static final Logger LOG = LoggerFactory.getLogger(ElasticsearchIndexer.class);
+	private static final Logger LOG = LoggerFactory.getLogger("etl");
 	private String hostname;
 	private String clustername;
 	private BulkRequestBuilder bulkRequest;

src/main/java/org/lobid/resources/EtikettJson.java

@@ -33,7 +33,7 @@
 @Out(String.class)
 public final class EtikettJson
     extends DefaultObjectPipe<String, ObjectReceiver<String>> {
-  private static final Logger LOG = LoggerFactory.getLogger(EtikettJson.class);
+  private static final Logger LOG = LoggerFactory.getLogger("etl");
   private String labelsDirectoryName = "labels";
   private String contextFilenameLocation;
   private boolean generateContext = false;

src/main/java/org/lobid/resources/JsonLdEtikett.java

@@ -28,7 +28,7 @@
 @Out(HashMap.class)
 public final class JsonLdEtikett extends
 		DefaultObjectPipe<Map<String, Object>, ObjectReceiver<Map<String, Object>>> {
-	private static final Logger LOG = LoggerFactory.getLogger(JsonLdEtikett.class);
+	private static final Logger LOG = LoggerFactory.getLogger("etl");
 	private static String labelsDirectoryName = "labels";
 	private static String contextFilenameLocation = "web/conf/context.jsonld";
 

src/main/java/org/lobid/resources/run/AlmaMarcXmlFix2lobidJsonEs.java

@@ -58,7 +58,7 @@ public class AlmaMarcXmlFix2lobidJsonEs {
     private static String triggerWebhookData;
     private static String kind = "";
     private static boolean switchAutomatically = false;
-    private static final Logger LOG = LoggerFactory.getLogger(AlmaMarcXmlFix2lobidJsonEs.class);
+    private static final Logger LOG = LoggerFactory.getLogger("etl");
     public static boolean threadAlreadyStarted = false;
     private static String switchAlias1;
     private static String switchAlias2;

src/main/java/org/lobid/resources/run/SwitchEsAlmaAlias.java

@@ -35,7 +35,7 @@ public final class SwitchEsAlmaAlias {
   private static final int DOCS_MINIMUM = 83000000;
   private static final int BYTES_MINIMUM = 49 * 1024 * 1024 * 1024;
   private static ObjectMapper objectMapper = new ObjectMapper();
-  private static final Logger LOG = LoggerFactory.getLogger(SwitchEsAlmaAlias.class);
+  private static final Logger LOG = LoggerFactory.getLogger("etl");
   private static StringBuilder logMessages = new StringBuilder(512);
 
   private SwitchEsAlmaAlias() {

src/main/java/org/lobid/resources/run/UpdateAliases.java

@@ -41,7 +41,7 @@
  */
 public class UpdateAliases {
   private static ObjectMapper objectMapper = new ObjectMapper();
-  private static final Logger LOG = LoggerFactory.getLogger(UpdateAliases.class);
+  private static final Logger LOG = LoggerFactory.getLogger("etl");
   private static boolean success = false;
   private static String logMessage;
   private static StringBuilder logMessages = new StringBuilder(512);

src/main/resources/log4j.xml

@@ -7,8 +7,8 @@
         </layout>
     </appender>
     <appender name="file" class="org.apache.log4j.FileAppender">
-        <param name="File" value="log/java.log"/>
-        <param name="Append" value="false"/>
+        <param name="File" value="./logs/java.log"/>
+        <param name="Append" value="true"/>
         <layout class="org.apache.log4j.PatternLayout">
             <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %p %t %c - %m%n"/>
         </layout>

src/main/resources/log4j2.xml

@@ -1,7 +1,7 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <Configuration>
   <Appenders>
-      <RollingFile name="RollingFile" fileName="logs/ETL.log" filePattern="ETL-log-%d{yyyy-ww}.gz" immediateFlush="true" append="true">
+      <RollingFile name="RollingFile" fileName="logs/etl-externallibs.log" filePattern="ETL-log-%d{yyyy-ww}.gz" immediateFlush="true" append="true">
           <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} %level [%l] - %m%n"/>
           <!-- Weekly rollover with compression -->
           <Policies>

src/main/resources/logback.xml

@@ -0,0 +1,47 @@
+<configuration>
+  <conversionRule conversionWord="coloredLevel" converterClass="play.api.Logger$ColoredLevel" />
+  <appender name="FILE_ETL" class="ch.qos.logback.core.rolling.RollingFileAppender">
+    <file>etl.log</file>
+    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
+        <!-- Daily rollover with compression -->
+        <fileNamePattern>etl-log-%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
+        <!-- keep 3 weeks worth of history -->
+        <maxHistory>21</maxHistory>
+        <!-- roll log file > 100MB -->
+        <maxFileSize>100MB</maxFileSize>
+    </rollingPolicy>
+    <encoder>
+        <pattern>%date{yyyy-MM-dd HH:mm:ss} [%level] %class{0} in %thread - %message%n%xException</pattern>
+    </encoder>
+  </appender>
+
+  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>%coloredLevel %logger{15} - %message%n%xException{10}</pattern>
+    </encoder>
+  </appender>
+
+  <appender name="ASYNCFILE" class="ch.qos.logback.classic.AsyncAppender">
+    <appender-ref ref="FILE_ETL" />
+  </appender>
+
+  <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
+    <appender-ref ref="STDOUT" />
+  </appender>
+
+  <!-- Off these ones as they are annoying, and anyway we manage configuration ourself -->
+  <logger name="com.avaje.ebean.config.PropertyMapLoader" level="OFF" />
+  <logger name="com.avaje.ebeaninternal.server.core.XmlConfigLoader" level="OFF" />
+  <logger name="com.avaje.ebeaninternal.server.lib.BackgroundThread" level="OFF" />
+  <logger name="com.gargoylesoftware.htmlunit.javascript" level="OFF" />
+
+  <logger name="etl" level="INFO" >
+    <appender-ref ref="FILE_ETL" />
+  </logger>
+
+  <root level="INFO">
+    <appender-ref ref="ASYNCFILE" />
+    <appender-ref ref="ASYNCSTDOUT" />
+  </root>
+
+</configuration>

src/test/java/org/lobid/resources/AlmaMarc21XmlToLobidJsonMetafixTest.java

@@ -45,7 +45,7 @@ public final class AlmaMarc21XmlToLobidJsonMetafixTest {
     private static final File DIRECTORY = new File(DIRECTORY_NAME);
     final HashMap<String, String> fixVariables = new HashMap<>();
     private static final boolean GENERATE_TESTDATA = System.getProperty("generateTestData", "false").equals("true");
-    private static final Logger LOG = LoggerFactory.getLogger(AlmaMarc21XmlToLobidJsonMetafixTest.class);
+    private static final Logger LOG = LoggerFactory.getLogger("etl");
     // try patterns like e.g."662", NOT".*662" (which just would slow down)
     private static final String PATTERN_TO_IDENTIFY_XML_RECORDS = "";
 

web/app/controllers/resources/WebhookAlmaFix.java

@@ -2,10 +2,10 @@
 
 package controllers.resources;
 
+import ch.qos.logback.classic.LoggerContext;
 import com.typesafe.config.Config;
 import com.typesafe.config.ConfigFactory;
 import org.lobid.resources.run.AlmaMarcXmlFix2lobidJsonEs;
-import play.Logger;
 import play.mvc.Controller;
 import play.mvc.Http;
 import play.mvc.Result;
@@ -20,6 +20,9 @@
 import java.util.List;
 import java.util.Objects;
 
+import ch.qos.logback.classic.Logger;
+import org.slf4j.LoggerFactory;
+
 /**
  * Webhook listener starting update/basedump process for the Alma Fix ETL. Also use
  * to switch ES index alias. Reloads "webhook" configs dynamically, i.e. every
@@ -55,6 +58,7 @@ public class WebhookAlmaFix extends Controller {
           + MSG_ETL_PROCESS_IS_ALREADY_RUNNING;
   private static final String MSG_CALLED_FROM_REMOTE_ADDRESS = "Called from: '%s' ";
   private static final String FIX_FILENAME = "conf/alma/alma.fix";
+  private static final Logger etl = (ch.qos.logback.classic.Logger)LoggerFactory.getLogger("etl");
   // If null, create default values from Global settings
   public static String clusterHost = null;
   public static String clusterName = null;
@@ -84,7 +88,7 @@ public static Result updateAlma(final String GIVEN_TOKEN) {
     try {
       msg = composeMessage(MSG_FILE_TOO_SMALL);
       if (Files.size(Paths.get(filenameUpdate.split(";")[0])) < 512) {
-        Logger.error(msg);
+        etl.error(msg);
         AlmaMarcXmlFix2lobidJsonEs.sendMail("Triggering of " + ETL_OF + KIND, false,
             msg);
         return status(500, msg);
@@ -103,7 +107,7 @@ public static Result updateAlma(final String GIVEN_TOKEN) {
       return status(423, msg);
     }
     msg = composeMessage(String.format(msgStartEtl, KIND));
-    Logger.info(msg);
+    etl.info(msg);
     AlmaMarcXmlFix2lobidJsonEs.setKindOfEtl(KIND);
     AlmaMarcXmlFix2lobidJsonEs.setSwitchAliasAfterETL(false);
     AlmaMarcXmlFix2lobidJsonEs.main(filenameUpdate, indexNameOfUpdate,
@@ -117,7 +121,7 @@ public static Result updateAlma(final String GIVEN_TOKEN) {
 
   private static void reloadConfigs() {
     Config config = ConfigFactory.parseFile(new File(RESOURCES_CONF)).resolve();
-    Logger.info("reload configs:" + RESOURCES_CONF);
+    etl.info("reload configs:" + RESOURCES_CONF);
     filenameUpdate = config.getString("webhook.alma.update.filename");
     filenameBasedump = config.getString("webhook.alma.basedump.filename");
     indexNameOfBasedump = config.getString("webhook.alma.basedump.indexname");
@@ -153,7 +157,7 @@ public static Result basedumpAlma(final String GIVEN_TOKEN) {
     try {
       if (Files.size(Paths.get(filenameBasedump)) < 512) {
         msg = composeMessage(MSG_FILE_TOO_SMALL);
-        Logger.error(msg);
+        etl.error(msg);
         AlmaMarcXmlFix2lobidJsonEs.sendMail("Triggering of " + ETL_OF + KIND, false,
             msg);
         return status(500, msg);
@@ -170,7 +174,7 @@ public static Result basedumpAlma(final String GIVEN_TOKEN) {
       return status(423, msg);
     }
     msg = composeMessage(String.format(msgStartEtl, KIND));
-    Logger.info(msg);
+    etl.info(msg);
     AlmaMarcXmlFix2lobidJsonEs.setKindOfEtl(KIND);
     if (basedumpSwitchAutomatically.equals("true")) {
       AlmaMarcXmlFix2lobidJsonEs.setSwitchAliasAfterETL(true);
@@ -198,9 +202,9 @@ public static Result switchEsAlias(final String GIVEN_TOKEN) {
     reloadConfigs();
     String subject = "switch aliases '" + alias1 + "' with '" + alias2 + "'";
     String msg = composeMessage(subject);
-    Logger.info(msg);
+    etl.info(msg);
     if (!GIVEN_TOKEN.equals(token)) {
-      Logger.info("Wrong token: " + GIVEN_TOKEN);
+      etl.info("Wrong token: " + GIVEN_TOKEN);
       return wrongToken(subject, GIVEN_TOKEN);
     }
     boolean success;
@@ -222,7 +226,7 @@ public static Result switchEsAlias(final String GIVEN_TOKEN) {
   private static Result wrongToken(final String KIND,
       final String GIVEN_TOKEN) {
     String msg = composeMessage(String.format(msgWrongToken, GIVEN_TOKEN, KIND));
-    Logger.error(msg);
+    etl.error(msg);
     AlmaMarcXmlFix2lobidJsonEs.sendMail(KIND, false, msg);
     return forbidden(msg);
   }

web/conf/logback.xml

@@ -1,10 +1,11 @@
 <configuration>
   <conversionRule conversionWord="coloredLevel" converterClass="play.api.Logger$ColoredLevel" />
-  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
+  <appender name="FILE_APPLICATION" class="ch.qos.logback.core.rolling.RollingFileAppender">
     <file>./logs/application.log</file>
     <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
         <!-- Daily rollover with compression -->
         <fileNamePattern>application-log-%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
+         <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} %level [%l] - %m%n"/>
         <!-- keep 3 weeks worth of history -->
         <maxHistory>21</maxHistory>
         <!-- roll log file > 100MB -->
@@ -13,6 +14,21 @@
     <encoder>
       <pattern>%date{yyyy-MM-dd HH:mm:ss ZZZZ} [%level] from %logger in %thread - %message%n%xException</pattern>
     </encoder>
+</appender>
+
+  <appender name="FILE_ETL" class="ch.qos.logback.core.rolling.RollingFileAppender">
+    <file>./logs/etl.log</file>
+    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
+        <!-- Daily rollover with compression -->
+        <fileNamePattern>etl-log-%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
+        <!-- keep 3 weeks worth of history -->
+        <maxHistory>21</maxHistory>
+        <!-- roll log file > 100MB -->
+        <maxFileSize>100MB</maxFileSize>
+    </rollingPolicy>
+    <encoder>
+        <pattern>%date{yyyy-MM-dd HH:mm:ss} [%level] %class{0} in %thread - %message%n%xException</pattern>
+    </encoder>
   </appender>
 
   <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
@@ -22,7 +38,7 @@
   </appender>
 
   <appender name="ASYNCFILE" class="ch.qos.logback.classic.AsyncAppender">
-    <appender-ref ref="FILE" />
+    <appender-ref ref="FILE_APPLICATION" />
   </appender>
 
   <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
@@ -37,6 +53,9 @@
 
   <logger name="play" level="INFO" />
   <logger name="application" level="INFO" />
+  <logger name="etl" level="INFO" >
+    <appender-ref ref="FILE_ETL" />
+  </logger>
 
   <root level="INFO">
     <appender-ref ref="ASYNCFILE" />