JCE: switch WolfCryptDebug to use Java Logging

Author: cconlon

src/main/java/com/wolfssl/provider/jce/WolfCryptCipher.java

@@ -1074,8 +1074,8 @@ private String modeToString(CipherMode type) {
     }
 
     private void log(String msg) {
-        WolfCryptDebug.print("[Cipher, " + algString + "-" +
-            algMode + "] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[" + algString + "-" + algMode + "] " + msg);
     }
 
     @SuppressWarnings("deprecation")

src/main/java/com/wolfssl/provider/jce/WolfCryptDebug.java

@@ -21,10 +21,108 @@
 
 package com.wolfssl.provider.jce;
 
+import java.sql.Timestamp;
+import java.util.logging.*;
+import java.util.logging.Formatter;
+import java.util.logging.Handler;
+import java.util.function.Supplier;
+
 class WolfCryptDebug {
 
+    private static final Logger jceLogger =
+        Logger.getLogger("com.wolfssl.provider.jce");
+
     public static boolean DEBUG = checkProperty();
 
+    /** Error level debug message */
+    public static final String ERROR = "ERROR";
+
+    /** Info level debug message */
+    public static final String INFO = "INFO";
+
+    static {
+        configureLoggers();
+    }
+
+    /**
+     * Custom handler that flushes after each log record
+     */
+    private static class FlushingStreamHandler extends StreamHandler {
+        public FlushingStreamHandler() {
+            super(System.err, new WolfCryptFormatter());
+        }
+
+        @Override
+        public synchronized void publish(LogRecord record) {
+            super.publish(record);
+            flush();
+        }
+    }
+
+    /**
+     * Configure loggers based on system properties
+     */
+    private static void configureLoggers() {
+        /* Remove any existing handlers */
+        for (Handler handler : jceLogger.getHandlers()) {
+            jceLogger.removeHandler(handler);
+        }
+
+        /* Only configure handlers if debug is enabled */
+        if (DEBUG) {
+            /* Create custom handler that flushes after each log record */
+            FlushingStreamHandler handler = new FlushingStreamHandler();
+            handler.setFormatter(new WolfCryptFormatter());
+            jceLogger.addHandler(handler);
+        }
+
+        /* Set log levels based on debug properties */
+        jceLogger.setLevel(DEBUG ? Level.ALL : Level.OFF);
+
+        /* Disable parent handlers to prevent double logging */
+        jceLogger.setUseParentHandlers(false);
+    }
+
+    /**
+     * Custom formatter for log records
+     */
+    private static class WolfCryptFormatter extends Formatter {
+        @Override
+        public String format(LogRecord record) {
+            if (record == null) {
+                return "null record\n";
+            }
+
+            String sourceClass = record.getSourceClassName();
+            if (sourceClass == null) {
+                sourceClass = "";
+            } else {
+                /* Extract simple class name (after last dot) */
+                int lastDot = sourceClass.lastIndexOf('.');
+                if (lastDot != -1) {
+                    sourceClass = sourceClass.substring(lastDot + 1);
+                }
+            }
+
+            Level level = record.getLevel();
+            String levelStr = level != null ? level.getName() : "UNKNOWN";
+
+            long threadId = record.getThreadID();
+            String message = record.getMessage();
+            if (message == null) {
+                message = "";
+            }
+
+            return String.format("%s [%s %s: TID %d: %s] %s\n",
+                    new Timestamp(record.getMillis()),
+                    "wolfJCE",
+                    levelStr,
+                    threadId,
+                    sourceClass,
+                    message);
+        }
+    }
+
     private static boolean checkProperty() {
 
         String enabled = System.getProperty("wolfjce.debug");
@@ -36,10 +134,61 @@ private static boolean checkProperty() {
         return false;
     }
 
-    public static void print(String string) {
-        if (DEBUG) {
-            System.out.println("wolfJCE: " + string);
+    /**
+     * Refresh debug enabled/disabled flags based on current
+     * System properties.
+     */
+    public static synchronized void refreshDebugFlags() {
+        boolean oldDebug = DEBUG;
+
+        DEBUG = checkProperty();
+
+        /* Only reconfigure if debug state has changed */
+        if (oldDebug != DEBUG) {
+            configureLoggers();
         }
     }
-}
 
+    /**
+     * Print out debug message if debugging is enabled.
+     *
+     * @param <T> class type of cl
+     * @param cl class being called from to get debug info
+     * @param tag level of debug message, ie WolfCryptDebug.INFO
+     * @param messageSupplier supplier of message to be printed out
+     */
+    public static synchronized <T> void log(Class<T> cl, String tag,
+        Supplier<String> messageSupplier) {
+
+        log(cl, "wolfJCE", tag, 0, messageSupplier);
+    }
+
+    /**
+     * Print out debug message if debugging is enabled.
+     *
+     * @param <T> class type of cl
+     * @param cl class being called from to get debug info
+     * @param component component name, ie "wolfJCE"
+     * @param tag level of debug message, ie WolfCryptDebug.INFO
+     * @param nativePtr native pointer
+     * @param messageSupplier supplier of message to be printed out
+     */
+    public static synchronized <T> void log(Class<T> cl, String component,
+        String tag, long nativePtr, Supplier<String> messageSupplier) {
+
+        if (!DEBUG) {
+            return;
+        }
+
+        Level level = tag.equals(ERROR) ? Level.SEVERE : Level.INFO;
+
+        String className = cl.getSimpleName();
+        if (nativePtr != 0) {
+            className = className + ": " + nativePtr;
+        }
+
+        LogRecord record = new LogRecord(level, messageSupplier.get());
+        record.setSourceClassName(cl.getName());
+        jceLogger.log(record);
+    }
+}

src/main/java/com/wolfssl/provider/jce/WolfCryptKeyAgreement.java

@@ -554,7 +554,8 @@ private String typeToString(KeyAgreeType type) {
     }
 
     private void log(String msg) {
-        WolfCryptDebug.print("[KeyAgreement, " + algString + "] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[" + algString + "] " + msg);
     }
 
     @SuppressWarnings("deprecation")

src/main/java/com/wolfssl/provider/jce/WolfCryptKeyGenerator.java

@@ -104,7 +104,8 @@ private WolfCryptKeyGenerator(AlgoType type) {
      * @param msg Message string to log
      */
     private void log(String msg) {
-        WolfCryptDebug.print("[KeyGenerator, " + algString + "] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[" + this.algString + "] " + msg);
     }
 
     /**

src/main/java/com/wolfssl/provider/jce/WolfCryptKeyPairGenerator.java

@@ -407,7 +407,8 @@ private String typeToString(KeyType type) {
     }
 
     private void log(String msg) {
-        WolfCryptDebug.print("[KeyPairGenerator, " + algString + "] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[" + algString + "] " + msg);
     }
 
     @SuppressWarnings("deprecation")

src/main/java/com/wolfssl/provider/jce/WolfCryptMac.java

@@ -215,7 +215,8 @@ private String typeToString(HmacType type) {
     }
 
     private void log(String msg) {
-        WolfCryptDebug.print("[Mac, " + algString + "] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[" + algString + "] " + msg);
     }
 
     @SuppressWarnings("deprecation")

src/main/java/com/wolfssl/provider/jce/WolfCryptMessageDigestMd5.java

@@ -100,7 +100,8 @@ protected void engineUpdate(byte[] input, int offset, int len) {
     }
 
     private void log(String msg) {
-        WolfCryptDebug.print("[MessageDigest, MD5] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[MD5] " + msg);
     }
 
     @Override

src/main/java/com/wolfssl/provider/jce/WolfCryptMessageDigestSha.java

@@ -100,7 +100,8 @@ protected void engineUpdate(byte[] input, int offset, int len) {
     }
 
     private void log(String msg) {
-        WolfCryptDebug.print("[MessageDigest, SHA] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[SHA] " + msg);
     }
 
     @Override

src/main/java/com/wolfssl/provider/jce/WolfCryptMessageDigestSha224.java

@@ -105,7 +105,8 @@ protected int engineGetDigestLength() {
     }
 
     private void log(String msg) {
-        WolfCryptDebug.print("[MessageDigest, SHA224] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[SHA224] " + msg);
     }
 
     @Override

src/main/java/com/wolfssl/provider/jce/WolfCryptMessageDigestSha256.java

@@ -105,7 +105,8 @@ protected int engineGetDigestLength() {
     }
 
     private void log(String msg) {
-        WolfCryptDebug.print("[MessageDigest, SHA256] " + msg);
+        WolfCryptDebug.log(getClass(), WolfCryptDebug.INFO,
+            () -> "[SHA256] " + msg);
     }
 
     @Override