#1874 Format debug messages in log, use Java 8 date formatter

- Format debug messages properly in the authme.log as well
- Replace DateFormat with Java 8's DateTimeFormatter (which is thread-safe)

src/main/java/fr/xephi/authme/ConsoleLogger.java

@@ -1,7 +1,6 @@
 package fr.xephi.authme;
 
 import com.google.common.base.Throwables;
-import fr.xephi.authme.output.ConsoleLoggerFactory;
 import fr.xephi.authme.output.LogLevel;
 import fr.xephi.authme.settings.Settings;
 import fr.xephi.authme.settings.properties.PluginSettings;
@@ -14,14 +13,13 @@ import java.io.FileOutputStream;
 import java.io.IOException;
 import java.io.OutputStreamWriter;
 import java.nio.charset.StandardCharsets;
-import java.text.DateFormat;
+import java.text.MessageFormat;
-import java.text.SimpleDateFormat;
+import java.time.LocalDateTime;
-import java.util.Arrays;
+import java.time.format.DateTimeFormatter;
-import java.util.Date;
+import java.time.format.DateTimeFormatterBuilder;
 import java.util.function.Supplier;
 import java.util.logging.Level;
 import java.util.logging.Logger;
-import java.util.stream.Collectors;
 
 /**
  * AuthMe logger.
@@ -29,7 +27,12 @@ import java.util.stream.Collectors;
 public final class ConsoleLogger {
 
     private static final String NEW_LINE = System.getProperty("line.separator");
-    private static final DateFormat DATE_FORMAT = new SimpleDateFormat("[MM-dd HH:mm:ss]");
+    /** Formatter which formats dates to something like "[08-16 21:18:46]" for any given LocalDateTime. */
+    private static final DateTimeFormatter DATE_FORMAT = new DateTimeFormatterBuilder()
+        .appendLiteral('[')
+        .appendPattern("MM-dd HH:mm:ss")
+        .appendLiteral(']')
+        .toFormatter();
 
     // Outside references
     private static File logFile;
@@ -157,22 +160,7 @@ public final class ConsoleLogger {
      */
     public void debug(String message) {
         if (logLevel.includes(LogLevel.DEBUG)) {
-            String debugMessage = "[DEBUG] " + message;
+            logAndWriteWithDebugPrefix(message);
-            logger.info(debugMessage);
-            writeLog(debugMessage);
-        }
-    }
-
-    /**
-     * Log the DEBUG message from the supplier if enabled.
-     *
-     * @param msgSupplier the message supplier
-     */
-    public void debug(Supplier<String> msgSupplier) {
-        if (logLevel.includes(LogLevel.DEBUG)) {
-            String debugMessage = "[DEBUG] " + msgSupplier.get();
-            logger.info(debugMessage);
-            writeLog(debugMessage);
         }
     }
 
@@ -182,11 +170,10 @@ public final class ConsoleLogger {
      * @param message the message
      * @param param1 parameter to replace in the message
      */
+    // Avoids array creation if DEBUG level is disabled
     public void debug(String message, Object param1) {
         if (logLevel.includes(LogLevel.DEBUG)) {
-            String debugMessage = "[DEBUG] " + message;
+            debug(message, new Object[]{param1});
-            logger.log(Level.INFO, debugMessage, param1);
-            writeLog(debugMessage + " {" + param1 + "}");
         }
     }
 
@@ -212,13 +199,27 @@ public final class ConsoleLogger {
      */
     public void debug(String message, Object... params) {
         if (logLevel.includes(LogLevel.DEBUG)) {
-            String debugMessage = "[DEBUG] " + message;
+            logAndWriteWithDebugPrefix(MessageFormat.format(message, params));
-            logger.log(Level.INFO, debugMessage, params);
-            writeLog(debugMessage + " {"
-                + Arrays.stream(params).map(String::valueOf).collect(Collectors.joining(", ")) + "}");
         }
     }
 
+    /**
+     * Log the DEBUG message from the supplier if enabled.
+     *
+     * @param msgSupplier the message supplier
+     */
+    public void debug(Supplier<String> msgSupplier) {
+        if (logLevel.includes(LogLevel.DEBUG)) {
+            logAndWriteWithDebugPrefix(msgSupplier.get());
+        }
+    }
+
+    private void logAndWriteWithDebugPrefix(String message) {
+        String debugMessage = "[DEBUG] " + message;
+        logger.info(debugMessage);
+        writeLog(debugMessage);
+    }
+
     // --------
     // Helpers
     // --------
@@ -232,7 +233,7 @@ public final class ConsoleLogger {
                 fileWriter.flush();
             } catch (IOException ignored) {
             } finally {
-                closeSilently(fileWriter);
+                closeSafely(fileWriter);
                 fileWriter = null;
             }
         }
@@ -245,10 +246,7 @@ public final class ConsoleLogger {
      */
     private static void writeLog(String message) {
         if (fileWriter != null) {
-            String dateTime;
+            String dateTime = DATE_FORMAT.format(LocalDateTime.now());
-            synchronized (DATE_FORMAT) {
-                dateTime = DATE_FORMAT.format(new Date());
-            }
             try {
                 fileWriter.write(dateTime);
                 fileWriter.write(": ");
@@ -260,11 +258,12 @@ public final class ConsoleLogger {
         }
     }
 
-    private static void closeSilently(Closeable closeable) {
+    private static void closeSafely(Closeable closeable) {
         if (closeable != null) {
             try {
                 closeable.close();
-            } catch (IOException ignored) {
+            } catch (IOException e) {
+                logger.log(Level.SEVERE, "Failed to close resource", e);
             }
         }
     }
@@ -280,9 +279,8 @@ public final class ConsoleLogger {
                 fos = new FileOutputStream(logFile, true);
                 fileWriter = new OutputStreamWriter(fos, StandardCharsets.UTF_8);
             } catch (Exception e) {
-                closeSilently(fos);
+                closeSafely(fos);
-                ConsoleLoggerFactory.get(ConsoleLogger.class)
+                logger.log(Level.SEVERE, "Failed to create writer to AuthMe log file", e);
-                    .logException("Failed to create the log file:", e);
             }
         }
     }

src/test/java/fr/xephi/authme/ConsoleLoggerTest.java

@@ -20,8 +20,6 @@ import java.io.IOException;
 import java.nio.charset.StandardCharsets;
 import java.nio.file.Files;
 import java.util.List;
-import java.util.Objects;
-import java.util.logging.Level;
 import java.util.logging.Logger;
 
 import static org.hamcrest.Matchers.contains;
@@ -156,22 +154,22 @@ public class ConsoleLoggerTest {
 
         // when
         consoleLogger.debug("Got {0} entries", 17);
-        consoleLogger.debug("Player `{0}` is in world `{1}`", "Bobby", new World("world"));
+        consoleLogger.debug("Player `{0}` is in world `{1}`", "Bobby", new WorldDummy("world"));
         consoleLogger.debug("{0} quick {1} jump over {2} lazy {3} (reason: {4})", 5, "foxes", 3, "dogs", null);
         consoleLogger.debug(() -> "Too little too late");
 
         // then
-        verify(logger).log(Level.INFO, "[DEBUG] Got {0} entries", 17);
+        verify(logger).info("[DEBUG] Got 17 entries");
-        verify(logger).log(Level.INFO, "[DEBUG] Player `{0}` is in world `{1}`", new Object[]{"Bobby", new World("world")});
+        verify(logger).info("[DEBUG] Player `Bobby` is in world `w[world]`");
-        verify(logger).log(Level.INFO, "[DEBUG] {0} quick {1} jump over {2} lazy {3} (reason: {4})",
+        verify(logger).info("[DEBUG] 5 quick foxes jump over 3 lazy dogs (reason: null)");
-            new Object[]{5, "foxes", 3, "dogs", null});
         verify(logger).info("[DEBUG] Too little too late");
+        verifyNoMoreInteractions(logger);
 
         List<String> loggedLines = Files.readAllLines(logFile.toPath(), StandardCharsets.UTF_8);
         assertThat(loggedLines, contains(
-            containsString("[DEBUG] Got {0} entries {17}"),
+            containsString("[DEBUG] Got 17 entries"),
-            containsString("[DEBUG] Player `{0}` is in world `{1}` {Bobby, w[world]}"),
+            containsString("[DEBUG] Player `Bobby` is in world `w[world]`"),
-            containsString("[DEBUG] {0} quick {1} jump over {2} lazy {3} (reason: {4}) {5, foxes, 3, dogs, null}"),
+            containsString("[DEBUG] 5 quick foxes jump over 3 lazy dogs (reason: null)"),
             containsString("[DEBUG] Too little too late")));
     }
 
@@ -214,10 +212,10 @@ public class ConsoleLoggerTest {
         return settings;
     }
 
-    private static final class World {
+    private static final class WorldDummy {
         private final String name;
 
-        World(String name) {
+        WorldDummy(String name) {
             this.name = name;
         }
 
@@ -225,13 +223,5 @@ public class ConsoleLoggerTest {
         public String toString() {
             return "w[" + name + "]";
         }
-
-        @Override
-        public boolean equals(Object other) {
-            if (other instanceof World) {
-                return Objects.equals(this.name, ((World) other).name);
-            }
-            return false;
-        }
     }
 }