#2959 - Improve logging for lazy loading error due to "markAsDeleted"

ebean-api/src/main/java/io/ebean/bean/InterceptReadWrite.java

@@ -725,7 +725,7 @@ public final class InterceptReadWrite implements EntityBeanIntercept {
       loader.loadBean(this);
       if (lazyLoadFailure) {
         // failed when lazy loading this bean
-        throw new EntityNotFoundException("Lazy loading failed on type:" + owner.getClass().getName() + " id:" + ownerId + " - Bean has been deleted.");
+        throw new EntityNotFoundException("Lazy loading failed on type:" + owner.getClass().getName() + " id:" + ownerId + " - Bean has been deleted. BeanLoader: " + beanLoader);
       }
       // bean should be loaded and intercepting now. setLoaded() has
       // been called by the lazy loading mechanism

ebean-core/src/main/java/io/ebeaninternal/api/CoreLog.java

@@ -9,4 +9,5 @@ public final class CoreLog {
 
   public static final System.Logger log = AppLog.getLogger("io.ebean.core");
   public static final System.Logger internal = AppLog.getLogger("io.ebean.internal");
+  public static final System.Logger markedAsDeleted = AppLog.getLogger("io.ebean.MarkedAsDeleted");
 }

ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanRequest.java

@@ -6,10 +6,7 @@ import io.ebeaninternal.api.SpiQuery.Mode;
 import io.ebeaninternal.server.core.OrmQueryRequest;
 import io.ebeaninternal.server.deploy.BeanDescriptor;
 
-import java.util.ArrayList;
-import java.util.HashSet;
-import java.util.List;
-import java.util.Set;
+import java.util.*;
 
 /**
  * Request for loading ManyToOne and OneToOne relationships.
@@ -103,7 +100,7 @@ public final class LoadBeanRequest extends LoadRequest {
   /**
    * Load the beans into the L2 cache if that is requested and check for load failures due to deletes.
    */
-  public void postLoad(List<?> list) {
+  public Result postLoad(List<?> list) {
     Set<Object> loadedIds = new HashSet<>();
     BeanDescriptor<?> desc = loadBuffer.descriptor();
     // collect Ids and maybe load bean cache
@@ -114,6 +111,7 @@ public final class LoadBeanRequest extends LoadRequest {
       desc.cacheBeanPutAll(list);
     }
     if (lazyLoadProperty != null) {
+      Set<Object> missedIds = new HashSet<>();
       for (EntityBeanIntercept ebi : batch) {
         // check if the underlying row in DB was deleted. Mark the bean as 'failed' if
         // necessary but allow processing to continue until it is accessed by client code
@@ -121,8 +119,36 @@ public final class LoadBeanRequest extends LoadRequest {
         if (!loadedIds.contains(id)) {
           // assume this is logically deleted (hence not found)
           desc.markAsDeleted(ebi.getOwner());
+          missedIds.add(id);
         }
       }
+      return new Result(loadedIds, missedIds);
+    }
+    return EMPTY_RESULT;
+  }
+
+  static final Result EMPTY_RESULT = new Result(Collections.emptySet(),Collections.emptySet());
+
+  public static class Result {
+
+    private final Set<Object> loadedIds;
+    private final Set<Object> missedIds;
+
+    Result(Set<Object> loadedIds, Set<Object> missedIds) {
+      this.loadedIds = loadedIds;
+      this.missedIds = missedIds;
+    }
+
+    public boolean markedDeleted() {
+      return !missedIds.isEmpty();
+    }
+
+    public Set<Object> missedIds() {
+      return missedIds;
+    }
+
+    public Set<Object> loadedIds() {
+      return loadedIds;
     }
   }
 }

ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultBeanLoader.java

@@ -14,10 +14,11 @@ import io.ebeaninternal.server.deploy.BeanPropertyAssocMany;
 import io.ebeaninternal.server.transaction.DefaultPersistenceContext;
 
 import javax.persistence.EntityNotFoundException;
+import java.text.MessageFormat;
 import java.util.List;
 import java.util.Set;
 
-import static java.lang.System.Logger.Level.DEBUG;
+import static java.lang.System.Logger.Level.*;
 
 /**
  * Helper to handle lazy loading and refreshing of beans.
@@ -137,8 +138,12 @@ final class DefaultBeanLoader {
 
     SpiQuery<?> query = server.createQuery(loadRequest.beanType());
     loadRequest.configureQuery(query, idList);
-    List<?> list = executeQuery(loadRequest, query);
-    loadRequest.postLoad(list);
+    final List<?> list = executeQuery(loadRequest, query);
+    final LoadBeanRequest.Result result = loadRequest.postLoad(list);
+    if (result.markedDeleted() && CoreLog.markedAsDeleted.isLoggable(DEBUG)) {
+      String msg = MessageFormat.format("Loaded bean marked as deleted for missedIds:{0} loadedIds:{1} sql:{2} list:{3}", result.missedIds(), result.loadedIds(), query.getGeneratedSql(), list);
+      CoreLog.markedAsDeleted.log(DEBUG, msg, new RuntimeException("LoadBeanRequest markedAsDeleted"));
+    }
   }
 
   /**

ebean-core/src/main/java/io/ebeaninternal/server/query/SqlTreeLoadBean.java

@@ -5,6 +5,7 @@ import io.ebean.bean.EntityBean;
 import io.ebean.bean.EntityBeanIntercept;
 import io.ebean.bean.PersistenceContext;
 import io.ebean.core.type.ScalarDataReader;
+import io.ebeaninternal.api.CoreLog;
 import io.ebeaninternal.api.SpiQuery;
 import io.ebeaninternal.api.SpiQuery.Mode;
 import io.ebeaninternal.server.deploy.DbReadContext;
@@ -14,6 +15,8 @@ import io.ebeaninternal.server.deploy.id.IdBinder;
 import java.sql.SQLException;
 import java.util.Map;
 
+import static java.lang.System.Logger.Level.DEBUG;
+
 /**
  * Normal bean included in the query.
  */
@@ -211,6 +214,9 @@ class SqlTreeLoadBean implements SqlTreeLoad {
         contextBean = ((STreePropertyAssocOne)nodeBeanProp).valueAsEntityBean(parentBean);
         if (contextBean != null) {
           desc.markAsDeleted(contextBean);
+          if (CoreLog.markedAsDeleted.isLoggable(DEBUG)) {
+            CoreLog.markedAsDeleted.log(DEBUG, contextBean + " contextBean markedAsDeleted", new RuntimeException(contextBean + " contextBean markedAsDeleted"));
+          }
         }
       }
     }

ebean-test/src/test/resources/logback-test.xml

@@ -77,6 +77,7 @@
   <logger name="io.avaje.config" level="TRACE"/>
   <logger name="io.ebean.docker" level="DEBUG"/>
   <logger name="io.ebean.test" level="TRACE"/>
+  <logger name="io.ebean.MarkedAsDeleted" level="DEBUG"/>
 
 <!--  <logger name="io.ebean.DDL" level="DEBUG"/>-->