Added debug-level logging for BeanTableSchema and ImmutableTableSchema.

.changes/next-release/feature-AmazonDynamoDBEnhancedClient-860ea33.json

@@ -0,0 +1,6 @@
+{
+    "category": "Amazon DynamoDB Enhanced Client", 
+    "contributor": "", 
+    "type": "feature", 
+    "description": "Added logging to 'software.amazon.awssdk.enhanced.dynamodb.beans', which will assist when debugging the behavior of BeanTableSchema and ImmutableTableSchema."
+}

services-custom/dynamodb-enhanced/src/main/java/software/amazon/awssdk/enhanced/dynamodb/DefaultAttributeConverterProvider.java

@@ -139,8 +139,16 @@ public <T> AttributeConverter<T> converterFor(EnhancedType<T> type) {
      */
     @SuppressWarnings("unchecked")
     private <T> Optional<AttributeConverter<T>> findConverter(EnhancedType<T> type) {
-        log.debug(() -> "Loading converter for " + type + ".");
+        Optional<AttributeConverter<T>> converter = findConverterInternal(type);
+        if (converter.isPresent()) {
+            log.debug(() -> "Converter for " + type + ": " + converter.get().getClass().getTypeName());
+        } else {
+            log.debug(() -> "No converter available for " + type);
+        }
+        return converter;
+    }
 
+    private <T> Optional<AttributeConverter<T>> findConverterInternal(EnhancedType<T> type) {
         AttributeConverter<T> converter = (AttributeConverter<T>) converterCache.get(type);
         if (converter != null) {
             return Optional.of(converter);

services-custom/dynamodb-enhanced/src/main/java/software/amazon/awssdk/enhanced/dynamodb/TableSchema.java

@@ -108,6 +108,9 @@ static <T> ImmutableTableSchema<T> fromImmutableClass(Class<T> immutableClass) {
      * This is a moderately expensive operation, and should be performed sparingly. This is usually done once at
      * application startup.
      *
+     * If this table schema is not behaving as you expect, enable debug logging for
+     * 'software.amazon.awssdk.enhanced.dynamodb.beans'.
+     *
      * @param annotatedClass A class that has been annotated with DynamoDb enhanced client annotations.
      * @param <T> The type of the item this {@link TableSchema} will map records to.
      * @return An initialized {@link TableSchema}

services-custom/dynamodb-enhanced/src/main/java/software/amazon/awssdk/enhanced/dynamodb/internal/DynamoDbEnhancedLogger.java

@@ -0,0 +1,32 @@
+/*
+ * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License").
+ * You may not use this file except in compliance with the License.
+ * A copy of the License is located at
+ *
+ *  http://aws.amazon.com/apache2.0
+ *
+ * or in the "license" file accompanying this file. This file is distributed
+ * on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either
+ * express or implied. See the License for the specific language governing
+ * permissions and limitations under the License.
+ */
+
+package software.amazon.awssdk.enhanced.dynamodb.internal;
+
+import software.amazon.awssdk.annotations.SdkInternalApi;
+import software.amazon.awssdk.enhanced.dynamodb.mapper.BeanTableSchema;
+import software.amazon.awssdk.enhanced.dynamodb.mapper.ImmutableTableSchema;
+import software.amazon.awssdk.utils.Logger;
+
+@SdkInternalApi
+public class DynamoDbEnhancedLogger {
+    /**
+     * Logger used for to assist customers in debugging {@link BeanTableSchema} and {@link ImmutableTableSchema} loading.
+     */
+    public static final Logger BEAN_LOGGER = Logger.loggerFor("software.amazon.awssdk.enhanced.dynamodb.beans");
+
+    private DynamoDbEnhancedLogger() {
+    }
+}

services-custom/dynamodb-enhanced/src/main/java/software/amazon/awssdk/enhanced/dynamodb/mapper/BeanTableSchema.java

@@ -15,11 +15,14 @@
 
 package software.amazon.awssdk.enhanced.dynamodb.mapper;
 
+import static software.amazon.awssdk.enhanced.dynamodb.internal.DynamoDbEnhancedLogger.BEAN_LOGGER;
+
 import java.beans.BeanInfo;
 import java.beans.IntrospectionException;
 import java.beans.Introspector;
 import java.beans.PropertyDescriptor;
 import java.lang.annotation.Annotation;
+import java.lang.reflect.Constructor;
 import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.lang.reflect.Modifier;
@@ -96,6 +99,8 @@
  * Creating an {@link BeanTableSchema} is a moderately expensive operation, and should be performed sparingly. This is
  * usually done once at application startup.
  *
+ * If this table schema is not behaving as you expect, enable debug logging for 'software.amazon.awssdk.enhanced.dynamodb.beans'.
+ *
  * @param <T> The type of object that this {@link TableSchema} maps to.
  */
 @SdkPublicApi
@@ -122,6 +127,7 @@ public static <T> BeanTableSchema<T> create(Class<T> beanClass) {
     }
 
     private static <T> BeanTableSchema<T> create(Class<T> beanClass, MetaTableSchemaCache metaTableSchemaCache) {
+        debugLog(beanClass, () -> "Creating bean schema");
         // Fetch or create a new reference to this yet-to-be-created TableSchema in the cache
         MetaTableSchema<T> metaTableSchema = metaTableSchemaCache.getOrCreate(beanClass);
 
@@ -158,7 +164,8 @@ private static <T> StaticTableSchema<T> createStaticTableSchema(Class<T> beanCla
         DynamoDbBean dynamoDbBean = beanClass.getAnnotation(DynamoDbBean.class);
 
         if (dynamoDbBean == null) {
-            throw new IllegalArgumentException("A DynamoDb bean class must be annotated with @DynamoDbBean");
+            throw new IllegalArgumentException("A DynamoDb bean class must be annotated with @DynamoDbBean, but " +
+                                               beanClass.getTypeName() + " was not.");
         }
 
         BeanInfo beanInfo;
@@ -174,12 +181,12 @@ private static <T> StaticTableSchema<T> createStaticTableSchema(Class<T> beanCla
         StaticTableSchema.Builder<T> builder = StaticTableSchema.builder(beanClass)
                                                                 .newItemSupplier(newObjectSupplier);
 
-        builder.attributeConverterProviders(createConverterProvidersFromAnnotation(dynamoDbBean));
+        builder.attributeConverterProviders(createConverterProvidersFromAnnotation(beanClass, dynamoDbBean));
 
         List<StaticAttribute<T, ?>> attributes = new ArrayList<>();
 
         Arrays.stream(beanInfo.getPropertyDescriptors())
-              .filter(BeanTableSchema::isMappableProperty)
+              .filter(p -> isMappableProperty(beanClass, p))
               .forEach(propertyDescriptor -> {
                   DynamoDbFlatten dynamoDbFlatten = getPropertyAnnotation(propertyDescriptor, DynamoDbFlatten.class);
 
@@ -221,12 +228,14 @@ private static AttributeConfiguration resolveAttributeConfiguration(PropertyDesc
                                      .build();
     }
 
-    private static List<AttributeConverterProvider> createConverterProvidersFromAnnotation(DynamoDbBean dynamoDbBean) {
+    private static List<AttributeConverterProvider> createConverterProvidersFromAnnotation(Class<?> beanClass,
+                                                                                           DynamoDbBean dynamoDbBean) {
         Class<? extends AttributeConverterProvider>[] providerClasses = dynamoDbBean.converterProviders();
 
         return Arrays.stream(providerClasses)
-                .map(c -> (AttributeConverterProvider) newObjectSupplierForClass(c).get())
-                .collect(Collectors.toList());
+                     .peek(c -> debugLog(beanClass, () -> "Adding Converter: " + c.getTypeName()))
+                     .map(c -> (AttributeConverterProvider) newObjectSupplierForClass(c).get())
+                     .collect(Collectors.toList());
     }
 
     private static <T> StaticAttribute.Builder<T, ?> staticAttributeBuilder(PropertyDescriptor propertyDescriptor,
@@ -358,7 +367,9 @@ private static void addTagsToAttribute(StaticAttribute.Builder<?, ?> attributeBu
 
     private static <R> Supplier<R> newObjectSupplierForClass(Class<R> clazz) {
         try {
-            return ObjectConstructor.create(clazz, clazz.getConstructor());
+            Constructor<R> constructor = clazz.getConstructor();
+            debugLog(clazz, () -> "Constructor: " + constructor);
+            return ObjectConstructor.create(clazz, constructor);
         } catch (NoSuchMethodException e) {
             throw new IllegalArgumentException(
                 String.format("Class '%s' appears to have no default constructor thus cannot be used with the " +
@@ -368,12 +379,14 @@ private static <R> Supplier<R> newObjectSupplierForClass(Class<R> clazz) {
 
     private static <T, R> Function<T, R> getterForProperty(PropertyDescriptor propertyDescriptor, Class<T> beanClass) {
         Method readMethod = propertyDescriptor.getReadMethod();
+        debugLog(beanClass, () -> "Property " + propertyDescriptor.getDisplayName() + " read method: " + readMethod);
         return BeanAttributeGetter.create(beanClass, readMethod);
     }
 
     private static <T, R> BiConsumer<T, R> setterForProperty(PropertyDescriptor propertyDescriptor,
                                                              Class<T> beanClass) {
         Method writeMethod = propertyDescriptor.getWriteMethod();
+        debugLog(beanClass, () -> "Property " + propertyDescriptor.getDisplayName() + " write method: " + writeMethod);
         return BeanAttributeSetter.create(beanClass, writeMethod);
     }
 
@@ -386,10 +399,27 @@ private static String attributeNameForProperty(PropertyDescriptor propertyDescri
         return propertyDescriptor.getName();
     }
 
-    private static boolean isMappableProperty(PropertyDescriptor propertyDescriptor) {
-        return propertyDescriptor.getReadMethod() != null
-            && propertyDescriptor.getWriteMethod() != null
-            && getPropertyAnnotation(propertyDescriptor, DynamoDbIgnore.class) == null;
+    private static boolean isMappableProperty(Class<?> beanClass, PropertyDescriptor propertyDescriptor) {
+
+        if (propertyDescriptor.getReadMethod() == null) {
+            debugLog(beanClass, () -> "Ignoring bean property " + propertyDescriptor.getDisplayName() + " because it has no "
+                                      + "read (get/is) method.");
+            return false;
+        }
+
+        if (propertyDescriptor.getWriteMethod() == null) {
+            debugLog(beanClass, () -> "Ignoring bean property " + propertyDescriptor.getDisplayName() + " because it has no "
+                                      + "write (set) method.");
+            return false;
+        }
+
+        if (getPropertyAnnotation(propertyDescriptor, DynamoDbIgnore.class) != null) {
+            debugLog(beanClass, () -> "Ignoring bean property " + propertyDescriptor.getDisplayName() + " because it has "
+                                      + "@DynamoDbIgnore.");
+            return false;
+        }
+
+        return true;
     }
 
     private static <R extends Annotation> R getPropertyAnnotation(PropertyDescriptor propertyDescriptor,
@@ -401,6 +431,9 @@ private static <R extends Annotation> R getPropertyAnnotation(PropertyDescriptor
             return getterAnnotation;
         }
 
+        // TODO: It's a common mistake that superclasses might have annotations that the child classes do not inherit, but the
+        // customer expects them to be inherited. We should either allow inheriting those annotations, allow specifying an
+        // annotation to inherit them, or log when this situation happens.
         return setterAnnotation;
     }
 
@@ -409,5 +442,9 @@ private static List<? extends Annotation> propertyAnnotations(PropertyDescriptor
                              Arrays.stream(propertyDescriptor.getWriteMethod().getAnnotations()))
                      .collect(Collectors.toList());
     }
+
+    private static void debugLog(Class<?> beanClass, Supplier<String> logMessage) {
+        BEAN_LOGGER.debug(() -> beanClass.getTypeName() + " - " + logMessage.get());
+    }
 }
 

services-custom/dynamodb-enhanced/src/main/java/software/amazon/awssdk/enhanced/dynamodb/mapper/ImmutableTableSchema.java

@@ -15,7 +15,10 @@
 
 package software.amazon.awssdk.enhanced.dynamodb.mapper;
 
+import static software.amazon.awssdk.enhanced.dynamodb.internal.DynamoDbEnhancedLogger.BEAN_LOGGER;
+
 import java.lang.annotation.Annotation;
+import java.lang.reflect.Constructor;
 import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.lang.reflect.Modifier;
@@ -96,6 +99,8 @@
  * Creating an {@link ImmutableTableSchema} is a moderately expensive operation, and should be performed sparingly. This is
  * usually done once at application startup.
  *
+ * If this table schema is not behaving as you expect, enable debug logging for 'software.amazon.awssdk.enhanced.dynamodb.beans'.
+ *
  * @param <T> The type of object that this {@link TableSchema} maps to.
  */
 @SdkPublicApi
@@ -123,6 +128,8 @@ public static <T> ImmutableTableSchema<T> create(Class<T> immutableClass) {
 
     private static <T> ImmutableTableSchema<T> create(Class<T> immutableClass,
                                                       MetaTableSchemaCache metaTableSchemaCache) {
+        debugLog(immutableClass, () -> "Creating immutable schema");
+
         // Fetch or create a new reference to this yet-to-be-created TableSchema in the cache
         MetaTableSchema<T> metaTableSchema = metaTableSchemaCache.getOrCreate(immutableClass);
 
@@ -175,7 +182,7 @@ private static <T, B> StaticImmutableTableSchema<T, B>  createStaticImmutableTab
                                       .newItemBuilder(newBuilderSupplier, buildFunction);
 
         builder.attributeConverterProviders(
-            createConverterProvidersFromAnnotation(immutableClass.getAnnotation(DynamoDbImmutable.class)));
+            createConverterProvidersFromAnnotation(immutableClass, immutableClass.getAnnotation(DynamoDbImmutable.class)));
 
         List<ImmutableAttribute<T, B, ?>> attributes = new ArrayList<>();
 
@@ -210,14 +217,15 @@ private static <T, B> StaticImmutableTableSchema<T, B>  createStaticImmutableTab
         return builder.build();
     }
 
-    private static List<AttributeConverterProvider> createConverterProvidersFromAnnotation(
-        DynamoDbImmutable dynamoDbImmutable) {
+    private static List<AttributeConverterProvider> createConverterProvidersFromAnnotation(Class<?> immutableClass,
+                                                                                           DynamoDbImmutable dynamoDbImmutable) {
 
         Class<? extends AttributeConverterProvider>[] providerClasses = dynamoDbImmutable.converterProviders();
 
         return Arrays.stream(providerClasses)
-                .map(c -> (AttributeConverterProvider) newObjectSupplierForClass(c).get())
-                .collect(Collectors.toList());
+                     .peek(c -> debugLog(immutableClass, () -> "Adding Converter: " + c.getTypeName()))
+                     .map(c -> (AttributeConverterProvider) newObjectSupplierForClass(c).get())
+                     .collect(Collectors.toList());
     }
 
     private static <T, B> ImmutableAttribute.Builder<T, B, ?> immutableAttributeBuilder(
@@ -359,7 +367,9 @@ private static <T, R> Supplier<R> newObjectSupplier(ImmutableInfo<T> immutableIn
 
     private static <R> Supplier<R> newObjectSupplierForClass(Class<R> clazz) {
         try {
-            return ObjectConstructor.create(clazz, clazz.getConstructor());
+            Constructor<R> constructor = clazz.getConstructor();
+            debugLog(clazz, () -> "Constructor: " + constructor);
+            return ObjectConstructor.create(clazz, constructor);
         } catch (NoSuchMethodException e) {
             throw new IllegalArgumentException(
                 String.format("Builder class '%s' appears to have no default constructor thus cannot be used with " +
@@ -370,12 +380,14 @@ private static <R> Supplier<R> newObjectSupplierForClass(Class<R> clazz) {
     private static <T, R> Function<T, R> getterForProperty(ImmutablePropertyDescriptor propertyDescriptor,
                                                            Class<T> immutableClass) {
         Method readMethod = propertyDescriptor.getter();
+        debugLog(immutableClass, () -> "Property " + propertyDescriptor.name() + " read method: " + readMethod);
         return BeanAttributeGetter.create(immutableClass, readMethod);
     }
 
     private static <T, R> BiConsumer<T, R> setterForProperty(ImmutablePropertyDescriptor propertyDescriptor,
                                                              Class<T> builderClass) {
         Method writeMethod = propertyDescriptor.setter();
+        debugLog(builderClass, () -> "Property " + propertyDescriptor.name() + " write method: " + writeMethod);
         return BeanAttributeSetter.create(builderClass, writeMethod);
     }
 
@@ -419,5 +431,8 @@ private static AttributeConfiguration resolveAttributeConfiguration(ImmutablePro
                                      .build();
     }
 
+    private static void debugLog(Class<?> beanClass, Supplier<String> logMessage) {
+        BEAN_LOGGER.debug(() -> beanClass.getTypeName() + " - " + logMessage.get());
+    }
 }
 

services-custom/dynamodb-enhanced/src/test/resources/log4j2.properties

@@ -0,0 +1,24 @@
+#
+# Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License").
+# You may not use this file except in compliance with the License.
+# A copy of the License is located at
+#
+#  http://aws.amazon.com/apache2.0
+#
+# or in the "license" file accompanying this file. This file is distributed
+# on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either
+# express or implied. See the License for the specific language governing
+# permissions and limitations under the License.
+#
+
+status = warn
+
+appender.console.type = Console
+appender.console.name = ConsoleAppender
+appender.console.layout.type = PatternLayout
+appender.console.layout.pattern = %d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n%throwable
+
+rootLogger.level = debug
+rootLogger.appenderRef.stdout.ref = ConsoleAppender

services-custom/pom.xml

@@ -43,4 +43,28 @@
             </dependency>
         </dependencies>
     </dependencyManagement>
+
+    <dependencies>
+        <dependency>
+            <groupId>org.apache.logging.log4j</groupId>
+            <artifactId>log4j-api</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.apache.logging.log4j</groupId>
+            <artifactId>log4j-core</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.apache.logging.log4j</groupId>
+            <artifactId>log4j-slf4j-impl</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.slf4j</groupId>
+            <artifactId>jcl-over-slf4j</artifactId>
+            <scope>test</scope>
+            <version>${slf4j.version}</version>
+        </dependency>
+    </dependencies>
 </project>