Modify MarkedAsDeleted to ignore beans added during load

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

@@ -115,7 +115,7 @@ public InterceptReadWrite() {
 
   @Override
   public String toString() {
-    return "InterceptReadWrite{state=" + state +
+    return "InterceptReadWrite@" + hashCode() + "{state=" + state +
       (dirty ? " dirty;" : "") +
       (forceUpdate ? " forceUpdate;" : "") +
       (readOnly ? " readOnly;" : "") +

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

@@ -26,4 +26,6 @@ public interface LoadBeanBuffer {
   boolean isCache();
 
   void loadingStarted();
+
+  void loadingStopped();
 }

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

@@ -8,6 +8,8 @@
 
 import java.util.*;
 
+import static java.lang.System.Logger.Level.DEBUG;
+
 /**
  * Request for loading ManyToOne and OneToOne relationships.
  */
@@ -18,12 +20,13 @@ public final class LoadBeanRequest extends LoadRequest {
   private final String lazyLoadProperty;
   private final boolean loadCache;
   private final boolean alreadyLoaded;
-
+  private String triggerEbi;
   /**
    * Construct for lazy load request.
    */
   public LoadBeanRequest(LoadBeanBuffer loadBuffer, EntityBeanIntercept ebi, boolean loadCache) {
     this(loadBuffer, null, true, ebi.lazyLoadProperty(), ebi.isLoaded(), loadCache || ebi.isLoadedFromCache());
+    this.triggerEbi = String.valueOf(ebi);
   }
 
   /**
@@ -105,7 +108,8 @@ private String mode() {
   /**
    * Load the beans into the L2 cache if that is requested and check for load failures due to deletes.
    */
-  public Result postLoad(List<?> list) {
+  public Result postLoad(List<?> list, List<Object> queryIds) {
+    loadBuffer.loadingStopped();
     Set<Object> loadedIds = new HashSet<>();
     BeanDescriptor<?> desc = loadBuffer.descriptor();
     // collect Ids and maybe load bean cache
@@ -123,10 +127,17 @@ public Result postLoad(List<?> list) {
         // necessary but allow processing to continue until it is accessed by client code
         Object id = desc.getId(ebi.owner());
         if (!loadedIds.contains(id)) {
-          // assume this is logically deleted (hence not found)
-          desc.markAsDeleted(ebi.owner());
-          missedIds.add(id);
-          missed.add(ebi);
+          if (queryIds.contains(id)) {
+            // assume this is logically deleted (hence not found)
+            desc.markAsDeleted(ebi.owner());
+          } else {
+            // unexpected, added to batch during loading
+            missedIds.add(id);
+            missed.add(ebi);
+          }
+        }
+        if (!missed.isEmpty()) {
+          CoreLog.markedAsDeleted.log(DEBUG, "Loaded bean batch triggered by ebi:{0} property:{1}", triggerEbi, lazyLoadProperty);
         }
       }
       return new Result(loadedIds, missedIds, missed);
@@ -148,7 +159,7 @@ public static class Result {
       this.missed = missed;
     }
 
-    public boolean markedDeleted() {
+    public boolean hasMisses() {
       return !missedIds.isEmpty();
     }
 

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

@@ -142,13 +142,13 @@ void loadBean(LoadBeanRequest loadRequest) {
     final SpiQuery<?> query = server.createQuery(loadRequest.beanType());
     loadRequest.configureQuery(query, ids);
     final List<?> list = executeQuery(loadRequest, query);
-    final LoadBeanRequest.Result result = loadRequest.postLoad(list);
-    if (result.markedDeleted() && CoreLog.markedAsDeleted.isLoggable(DEBUG)) {
+    final LoadBeanRequest.Result result = loadRequest.postLoad(list, ids);
+    if (result.hasMisses() && CoreLog.markedAsDeleted.isLoggable(DEBUG)) {
       CoreLog.markedAsDeleted.log(DEBUG, "Loaded bean batch BEFORE {0}", batchBefore);
       CoreLog.markedAsDeleted.log(DEBUG, "Loaded bean batch AFTER {0}", batch);
-      String msg = MessageFormat.format("Loaded bean marked as deleted for {0} ids:{1} missedIds:{2} loadedIds:{3} sql:{4} loadedList:{5} missed:{6}",
-        loadRequest.beanType(), ids, result.missedIds(), result.loadedIds(), query.getGeneratedSql(), list, result.missed());
-      CoreLog.markedAsDeleted.log(DEBUG, msg, new RuntimeException("LoadBeanRequest markedAsDeleted"));
+      String msg = MessageFormat.format("Bean added to batch during load for {0} missedIds:{1} ids:{2} loadedIds:{3} sql:{4} missed:{5}",
+        loadRequest.beanType(), result.missedIds(), ids, result.loadedIds(), query.getGeneratedSql(), result.missed());
+      CoreLog.markedAsDeleted.log(DEBUG, msg, new RuntimeException("LoadBeanRequest - Bean added to batch during load"));
     }
   }
 

ebean-core/src/main/java/io/ebeaninternal/server/loadcontext/DLoadBeanContext.java

@@ -11,6 +11,7 @@
 import io.ebeaninternal.server.deploy.BeanPropertyAssocMany;
 import io.ebeaninternal.server.querydefn.OrmQueryProperties;
 
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.HashSet;
 import java.util.List;
@@ -71,6 +72,9 @@ void register(EntityBeanIntercept ebi) {
     if (currentBuffer.isFull()) {
       currentBuffer = createBuffer(batchSize);
     }
+    if (currentBuffer.addWhenLoading()) {
+      CoreLog.markedAsDeleted.log(DEBUG, "Adding " + ebi + " to batch " + currentBuffer + " after loadingStarted(1)", new RuntimeException("Adding to batch after load(1)"));
+    }
     ebi.setBeanLoader(currentBuffer, persistenceContext());
     currentBuffer.add(ebi);
   }
@@ -117,6 +121,7 @@ static class LoadBuffer implements BeanLoader, LoadBeanBuffer {
     private final DLoadBeanContext context;
     private final int batchSize;
     private final Set<EntityBeanIntercept> batch;
+    private final Instant whenCreated = Instant.now();
     private PersistenceContext persistenceContext;
 
     LoadBuffer(DLoadBeanContext context, int batchSize) {
@@ -127,7 +132,8 @@ static class LoadBuffer implements BeanLoader, LoadBeanBuffer {
 
     @Override
     public String toString() {
-      return "LoadBuffer@" + hashCode();
+      return "LoadBuffer@" + hashCode() + ":" + whenCreated + ":size=" + batch.size()
+        +":locked=" +bufferLock.isLocked()+ "/currentThread=" + bufferLock.isHeldByCurrentThread();
     }
 
     @Override
@@ -148,6 +154,10 @@ public boolean isFull() {
       return batchSize == batch.size();
     }
 
+    final boolean addWhenLoading() {
+      return loadingStarted.get() && CoreLog.markedAsDeleted.isLoggable(DEBUG);
+    }
+
     /**
      * Add the bean to the load buffer.
      */
@@ -156,11 +166,6 @@ public void add(EntityBeanIntercept ebi) {
         // get persistenceContext from first loaded bean into the buffer
         persistenceContext = ebi.persistenceContext();
       }
-      if (loadingStarted.get()) {
-        if (CoreLog.markedAsDeleted.isLoggable(DEBUG)) {
-          CoreLog.markedAsDeleted.log(DEBUG, "Adding to batch after loadingStarted(1)", new RuntimeException("Adding to batch after load(1"));
-        }
-      }
       batch.add(ebi);
     }
 
@@ -206,6 +211,11 @@ public void loadingStarted() {
       loadingStarted.set(true);
     }
 
+    @Override
+    public void loadingStopped() {
+      loadingStarted.set(false);
+    }
+
     @Override
     public void loadBean(EntityBeanIntercept ebi) {
       // A lock is effectively held by EntityBeanIntercept.loadBean()
@@ -217,7 +227,7 @@ public void loadBean(EntityBeanIntercept ebi) {
         // re-add to the batch and lazy load from DB skipping l2 cache
         if (loadingStarted.get()) {
           if (CoreLog.markedAsDeleted.isLoggable(DEBUG)) {
-            CoreLog.markedAsDeleted.log(DEBUG, "Adding to batch after loadingStarted(2)", new RuntimeException("Adding to batch after load(2"));
+            CoreLog.markedAsDeleted.log(DEBUG, "Adding " + ebi + "to batch " + this + "after loadingStarted(2) ", new RuntimeException("Adding to batch after load(2"));
           }
         }
         batch.add(ebi);
@@ -230,10 +240,8 @@ public void loadBean(EntityBeanIntercept ebi) {
         }
       }
 
-      LoadBeanRequest req = new LoadBeanRequest(this, ebi, context.hitCache);
-      context.desc.ebeanServer().loadBean(req);
+      context.desc.ebeanServer().loadBean(new LoadBeanRequest(this, ebi, context.hitCache));
       batch.clear();
-      loadingStarted.set(false);
     }
   }
 

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

@@ -247,7 +247,7 @@ private boolean isLazyLoadManyRoot() {
       return queryMode == Mode.LAZYLOAD_MANY && isRoot();
     }
 
-    private EntityBean getContextBean() {
+    private EntityBean contextBean() {
       return contextBean;
     }
 
@@ -358,7 +358,7 @@ private void initialise() throws SQLException {
     final EntityBean perform() throws SQLException {
       initialise();
       if (isLazyLoadManyRoot()) {
-        return getContextBean();
+        return contextBean();
       }
       postLoad();
       setBeanToParent();