Add more debug logic (corretto#167)

* Add more debug logic * Apply suggestions from code review Co-authored-by: Alex Chew <alex-chew@users.noreply.github.com> Co-authored-by: Alex Chew <alex-chew@users.noreply.github.com>
SalusaSecondus · Nov 24, 2021 · 23d692f · 23d692f
1 parent a72c6de
commit 23d692f
Show file tree

Hide file tree

Showing 9 changed files with 124 additions and 37 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,5 +1,18 @@
 # Changelog
 
+## 1.6.2 (Unreleased)
+
+### Improvements
+* Add "help" value to two of our properties which outputs (to STDERR) valid values.
+   * `com.amazon.corretto.crypto.provider.extrachecks`
+   * `com.amazon.corretto.crypto.provider.debug`
+* Add new `com.amazon.corretto.crypto.provider.debug` property to gate possibly expensive debug logic.
+Current values are:
+   * `FreeTrace` - Enables tracking of allocation and freeing of native objects from java for more detailed exceptions.
+   * `VerboseLogging` - Enables more detailed logging.
+   * `ALL` - Enables all of the above
+(May still require changes to your logging configuration to see the new logs.)
+
 ## 1.6.1
 ### Patches
 * Fix an issue where a race condition can cause ACCP's MessageDigest hashing algorithms to return the same value for different inputs [PR #157](https://github.com/corretto/amazon-corretto-crypto-provider/pull/157)

diff --git a/CMakeLists.txt b/CMakeLists.txt
@@ -109,6 +109,7 @@ set(ACCP_SRC
         src/com/amazon/corretto/crypto/provider/AesCtrDrbg.java
         src/com/amazon/corretto/crypto/provider/AesGcmSpi.java
         src/com/amazon/corretto/crypto/provider/ConstantTime.java
+        src/com/amazon/corretto/crypto/provider/DebugFlag.java
         src/com/amazon/corretto/crypto/provider/EcGen.java
         src/com/amazon/corretto/crypto/provider/EvpKeyAgreement.java
         src/com/amazon/corretto/crypto/provider/EvpKeyType.java
@@ -656,6 +657,7 @@ add_custom_target(check-junit-SecurityManager
 add_custom_target(check-junit-extra-checks
     COMMAND ${TEST_JAVA_EXECUTABLE}
         -Dcom.amazon.corretto.crypto.provider.extrachecks=ALL
+        -Dcom.amazon.corretto.crypto.provider.debug=ALL
         ${TEST_RUNNER_ARGUMENTS}
         --select-package=com.amazon.corretto.crypto.provider.test
         --exclude-package=com.amazon.corretto.crypto.provider.test.integration

diff --git a/src/com/amazon/corretto/crypto/provider/AmazonCorrettoCryptoProvider.java b/src/com/amazon/corretto/crypto/provider/AmazonCorrettoCryptoProvider.java
@@ -12,7 +12,6 @@
 import static java.util.logging.Logger.getLogger;
 
 import java.io.IOException;
-import java.io.ObjectStreamException;
 import java.lang.invoke.MethodHandle;
 import java.lang.invoke.MethodHandles;
 import java.lang.invoke.MethodType;
@@ -44,7 +43,7 @@ public final class AmazonCorrettoCryptoProvider extends java.security.Provider {
     private transient SelfTestSuite selfTestSuite = new SelfTestSuite();
 
     static {
-        if (!Loader.IS_AVAILABLE) {
+        if (!Loader.IS_AVAILABLE && DebugFlag.VERBOSELOGS.isEnabled()) {
             getLogger("AmazonCorrettoCryptoProvider").fine("Native JCE libraries are unavailable - disabling");
             rdRandSupported_ = false;
         } else {
@@ -268,23 +267,9 @@ private void resetAllSelfTests() {
     public AmazonCorrettoCryptoProvider() {
         super("AmazonCorrettoCryptoProvider", PROVIDER_VERSION, "");
 
-        final String[] extraCheckOptions = Loader.getProperty("extrachecks", "").split(",");
-        for (final String check : extraCheckOptions) {
-          if (check.equalsIgnoreCase("all")) {
-            extraChecks.addAll(EnumSet.allOf(ExtraCheck.class));
-            break;
-          }
-          try {
-            final ExtraCheck value = ExtraCheck.valueOf(check.toUpperCase());
-            if (value != null) {
-              extraChecks.add(value);
-            }
-          } catch (Exception ex) {
-            // Ignore
-          }
-        }
+        Utils.optionsFromProperty(ExtraCheck.class, extraChecks, "extrachecks");
 
-        if (!Loader.IS_AVAILABLE) {
+        if (!Loader.IS_AVAILABLE && DebugFlag.VERBOSELOGS.isEnabled()) {
             getLogger("AmazonCorrettoCryptoProvider").fine("Native JCE libraries are unavailable - disabling");
 
             // Don't implement anything
@@ -339,7 +324,7 @@ public static boolean isRdRandSupported() {
      * {@link SelfTestStatus#NOT_RUN} will be returned if any tests have not be run.
      * {@link SelfTestStatus#PASSED} will only be returned if all tests have been run and have
      * all passed.
-     * 
+     *
      * <p>Algorithms currently run by this method:
      * <ul>
      * <li>NIST800-90A/AES-CTR-256
@@ -349,7 +334,7 @@ public static boolean isRdRandSupported() {
      * <li>HMacSHA1
      * <li>HMacMD5
      * </ul>
-     * 
+     *
      * @see #runSelfTests()
      */
     public SelfTestStatus getSelfTestStatus() {
@@ -361,7 +346,7 @@ public SelfTestStatus getSelfTestStatus() {
      * Please see {@link #getSelfTestStatus()} for the algorithms tested and
      * the possible return values. (though this method will never return
      * {@link SelfTestStatus#NOT_RUN}).
-     * 
+     *
      * @see #getSelfTestStatus()
      */
     public SelfTestStatus runSelfTests() {
@@ -379,7 +364,7 @@ public Throwable getLoadingError() {
     /**
      * <p>Throws an instance of {@link RuntimeCryptoException} if this library is not currently
      * functional. Otherwise does nothing.
-     * 
+     *
      * <p>This library is considered healthy if {@link #getLoadingError()} returns {@code null}
      * and {@link #runSelfTests()} returns {@link SelfTestStatus#PASSED}.
      */

diff --git a/src/com/amazon/corretto/crypto/provider/DebugFlag.java b/src/com/amazon/corretto/crypto/provider/DebugFlag.java
@@ -0,0 +1,41 @@
+// Copyright Amazon.com Inc. or its affiliates. All Rights Reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+package com.amazon.corretto.crypto.provider;
+
+import java.util.EnumSet;
+
+/**
+ * Indicates whether a given debug mode is enabled for ACCP. None of these modes
+ * may compromise the security of ACCP but they are permitted to have
+ * significant performance costs.
+ *
+ * These are used by passing them by name (case-insensitive) to the
+ * {@code com.amazon.corretto.crypto.provider.debug} system property. Example:
+ * {@code -Dcom.amazon.corretto.crypto.provider.debug=FreeTrace}.
+ *
+ * Alternatively you can enable all debug flags with the magic value of "ALL".
+ */
+enum DebugFlag {
+    /** Trace when native values are created and freed. */
+    FREETRACE,
+    /**
+     * Increases the verbosity of logs.
+     * May still need to be combined with increasing the log level of your configured logger.
+     */
+    VERBOSELOGS;
+
+    private static final EnumSet<DebugFlag> ENABLED_FLAGS = EnumSet.noneOf(DebugFlag.class);
+
+    static {
+        Utils.optionsFromProperty(DebugFlag.class, ENABLED_FLAGS, "debug");
+    }
+
+    static boolean isEnabled(final DebugFlag flag) {
+        return ENABLED_FLAGS.contains(flag);
+    }
+
+    boolean isEnabled() {
+        return isEnabled(this);
+    }
+}
diff --git a/src/com/amazon/corretto/crypto/provider/Loader.java b/src/com/amazon/corretto/crypto/provider/Loader.java
@@ -44,7 +44,7 @@
  * </ol>
  */
 final class Loader {
-    private static final String PROPERTY_BASE = "com.amazon.corretto.crypto.provider.";
+    static final String PROPERTY_BASE = "com.amazon.corretto.crypto.provider.";
     private static final String LIBRARY_NAME = "amazonCorrettoCryptoProvider";
     private static final Pattern TEST_FILENAME_PATTERN = Pattern.compile("[-a-zA-Z0-9]+(\\.[a-zA-Z0-9]+)*");
     private static final Logger LOG = Logger.getLogger("AmazonCorrettoCryptoProvider");
@@ -176,10 +176,12 @@ static String getProperty(String propertyName, String def) {
         }
         IS_AVAILABLE = available;
         LOADING_ERROR = error;
-        if (available) {
-            LOG.log(Level.CONFIG, "Successfully loaded native library version " + PROVIDER_VERSION_STR);
-        } else {
-            LOG.log(Level.CONFIG, "Unable to load native library", error);
+        if (DebugFlag.VERBOSELOGS.isEnabled()) {
+            if (available) {
+                LOG.log(Level.CONFIG, "Successfully loaded native library version " + PROVIDER_VERSION_STR);
+            } else {
+                LOG.log(Level.CONFIG, "Unable to load native library", error);
+            }
         }
 
         // Finally start up a cleaning thread if necessary
@@ -270,7 +272,9 @@ private synchronized static Path createTmpFile(final String prefix, final String
 
                 try {
                     final Path result = Files.createFile(tmpFile, permissions);
-                    LOG.log(Level.FINE, "Created temporary library file after " + attempt + " attempts");
+                    if (DebugFlag.VERBOSELOGS.isEnabled()) {
+                        LOG.log(Level.FINE, "Created temporary library file after " + attempt + " attempts");
+                    }
                     return result;
                 } catch (final FileAlreadyExistsException ex) {
                     // We ignore and retry this exception

diff --git a/src/com/amazon/corretto/crypto/provider/NativeResource.java b/src/com/amazon/corretto/crypto/provider/NativeResource.java
@@ -20,6 +20,12 @@ private static void wakeCleaner() {
 
     private static final class Cell extends ReentrantLock {
         private static final long serialVersionUID = 1L;
+        // Debug stuff
+        private static final boolean FREE_TRACE_DEBUG = DebugFlag.FREETRACE.isEnabled();
+        private Throwable creationTrace;
+        private Throwable freeTrace;
+        // End debug stuff
+
         // @GuardedBy("this") // Restore once replacement for JSR-305 available
         private final long ptr;
         private final LongConsumer releaser;
@@ -33,6 +39,7 @@ private Cell(final long ptr, final LongConsumer releaser) {
             this.ptr = ptr;
             this.releaser = releaser;
             this.released = false;
+            this.creationTrace = buildFreeTrace("Created", null);
         }
 
         public void release() {
@@ -41,6 +48,7 @@ public void release() {
                 if (released) return;
 
                 released = true;
+                freeTrace = buildFreeTrace("Freed", creationTrace);
                 releaser.accept(ptr);
             } finally {
                 unlock();
@@ -50,11 +58,9 @@ public void release() {
         public long take() {
             lock();
             try {
-                if (released) {
-                    throw new IllegalStateException("Use after free");
-                }
-
+                assertNotFreed();
                 released = true;
+                freeTrace = buildFreeTrace("Freed", creationTrace);
                 return ptr;
             } finally {
                 unlock();
@@ -78,14 +84,25 @@ public boolean isReleased() {
         public <T> T use(LongFunction<T> function) {
             lock();
             try {
-                if (released) {
-                    throw new IllegalStateException("Use after free");
-                }
+                assertNotFreed();
                 return function.apply(ptr);
             } finally {
                 unlock();
             }
         }
+
+        private void assertNotFreed() {
+            if (released) {
+                throw new IllegalStateException("Use after free", freeTrace);
+            }
+        }
+
+        private static Throwable buildFreeTrace(final String message, final Throwable cause) {
+            if (!FREE_TRACE_DEBUG) {
+                return null;
+            }
+            return new RuntimeCryptoException(message + " in Thread " + Thread.currentThread().getName(), cause);
+        }
     }
 
     private final Cell cell;

diff --git a/src/com/amazon/corretto/crypto/provider/SelfTestSuite.java b/src/com/amazon/corretto/crypto/provider/SelfTestSuite.java
@@ -67,7 +67,7 @@ public SelfTestResult runTest() {
         private SelfTestResult runTest0() {
             SelfTestResult localResult = selfTestRunner.get();
 
-            if (localResult.getStatus() == SelfTestStatus.PASSED) {
+            if (localResult.getStatus() == SelfTestStatus.PASSED && DebugFlag.VERBOSELOGS.isEnabled()) {
                 LOGGER.finer(() -> String.format("Self-test result for JCE algo %s: PASSED",
                                                  getAlgorithmName()));
             } else {

diff --git a/src/com/amazon/corretto/crypto/provider/Utils.java b/src/com/amazon/corretto/crypto/provider/Utils.java
@@ -16,6 +16,7 @@
 import java.security.spec.PKCS8EncodedKeySpec;
 import java.security.spec.X509EncodedKeySpec;
 import java.util.Arrays;
+import java.util.EnumSet;
 
 import javax.crypto.Cipher;
 import javax.crypto.Mac;
@@ -410,5 +411,29 @@ static void zeroByteBuffer(ByteBuffer buffer) {
             buffer.put(src);
         }
     }
+
+    static <E extends Enum<E>> void optionsFromProperty(
+        final Class<E> clazz, final EnumSet<E> set, final String propertyName) {
+        final String propertyValue = Loader.getProperty(propertyName, "");
+        if (propertyValue.equalsIgnoreCase("help")) {
+            System.err.format("Valid values for %s%s are: %s or ALL",
+                Loader.PROPERTY_BASE, propertyName, EnumSet.allOf(clazz));
+        }
+        final String[] extraCheckOptions = propertyValue.split(",");
+        for (final String check : extraCheckOptions) {
+            if (check.equalsIgnoreCase("all")) {
+                set.addAll(EnumSet.allOf(clazz));
+                break;
+            }
+            try {
+                final E value = Enum.valueOf(clazz, check.toUpperCase());
+                if (value != null) {
+                    set.add(value);
+                }
+            } catch (Exception ex) {
+                // Ignore
+            }
+        }
+    }
 }
 
diff --git a/tst/com/amazon/corretto/crypto/provider/test/UtilsTest.java b/tst/com/amazon/corretto/crypto/provider/test/UtilsTest.java
@@ -31,7 +31,7 @@ public class UtilsTest {
         try {
             UTILS_CLASS = Class.forName("com.amazon.corretto.crypto.provider.Utils");
         } catch (final ClassNotFoundException ex) {
-            throw new AssertionError(ex); 
+            throw new AssertionError(ex);
         }
     }