Merge pull request #3002 from ebean-orm/feature/improveLogging-markedAsDeleted

Improve the logging around MarkedAsDeleted

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

@@ -24,6 +24,11 @@ public class InterceptReadOnly implements EntityBeanIntercept {
     this.owner = (EntityBean) ownerBean;
   }
 
+  @Override
+  public String toString() {
+    return "InterceptReadOnly{" + owner + '}';
+  }
+
   @Override
   public EntityBean getOwner() {
     return owner;

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

@@ -113,6 +113,25 @@ public final class InterceptReadWrite implements EntityBeanIntercept {
     this.flags = null;
   }
 
+  @Override
+  public String toString() {
+    return "InterceptReadWrite{state=" + state +
+      (dirty ? " dirty;" : "") +
+      (forceUpdate ? " forceUpdate;" : "") +
+      (readOnly ? " readOnly;" : "") +
+      (disableLazyLoad ? " disableLazyLoad;" : "") +
+      (lazyLoadFailure ? " lazyLoadFailure;" : "") +
+      (fullyLoadedBean ? " fullyLoadedBean;" : "") +
+      (loadedFromCache ? " loadedFromCache;" : "") +
+      ", pc=" + System.identityHashCode(persistenceContext) +
+      ", flags=" + Arrays.toString(flags) +
+      (lazyLoadProperty > -1 ? (", lazyLoadProperty=" + lazyLoadProperty) : "") +
+      ", loader=" + beanLoader +
+      (ownerId != null ? (", ownerId=" + ownerId) : "") +
+      ", owner=" + owner +
+      '}';
+  }
+
   @Override
   public EntityBean getOwner() {
     return owner;
@@ -718,7 +737,7 @@ public final class InterceptReadWrite implements EntityBeanIntercept {
     }
     if (lazyLoadFailure) {
       // failed when batch lazy loaded by another bean in the batch
-      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);
     }
     if (lazyLoadProperty == -1) {
       lazyLoadProperty = loadProperty;

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

@@ -62,9 +62,9 @@ public final class LoadBeanRequest extends LoadRequest {
   /**
    * Return the list of Id values for the beans in the lazy load buffer.
    */
-  public List<Object> getIdList() {
-    List<Object> idList = new ArrayList<>();
-    BeanDescriptor<?> desc = loadBuffer.descriptor();
+  public List<Object> ids() {
+    final List<Object> idList = new ArrayList<>(batch.size());
+    final BeanDescriptor<?> desc = loadBuffer.descriptor();
     for (EntityBeanIntercept ebi : batch) {
       idList.add(desc.getId(ebi.getOwner()));
     }
@@ -111,6 +111,7 @@ public final class LoadBeanRequest extends LoadRequest {
       desc.cacheBeanPutAll(list);
     }
     if (lazyLoadProperty != null) {
+      List<EntityBeanIntercept> missed = new ArrayList<>();
       Set<Object> missedIds = new HashSet<>();
       for (EntityBeanIntercept ebi : batch) {
         // check if the underlying row in DB was deleted. Mark the bean as 'failed' if
@@ -120,23 +121,26 @@ public final class LoadBeanRequest extends LoadRequest {
           // assume this is logically deleted (hence not found)
           desc.markAsDeleted(ebi.getOwner());
           missedIds.add(id);
+          missed.add(ebi);
         }
       }
-      return new Result(loadedIds, missedIds);
+      return new Result(loadedIds, missedIds, missed);
     }
     return EMPTY_RESULT;
   }
 
-  static final Result EMPTY_RESULT = new Result(Collections.emptySet(),Collections.emptySet());
+  static final Result EMPTY_RESULT = new Result(Collections.emptySet(),Collections.emptySet(), Collections.emptyList());
 
   public static class Result {
 
     private final Set<Object> loadedIds;
     private final Set<Object> missedIds;
+    private final List<EntityBeanIntercept> missed;
 
-    Result(Set<Object> loadedIds, Set<Object> missedIds) {
+    Result(Set<Object> loadedIds, Set<Object> missedIds, List<EntityBeanIntercept> missed) {
       this.loadedIds = loadedIds;
       this.missedIds = missedIds;
+      this.missed = missed;
     }
 
     public boolean markedDeleted() {
@@ -150,5 +154,9 @@ public final class LoadBeanRequest extends LoadRequest {
     public Set<Object> loadedIds() {
       return loadedIds;
     }
+
+    public List<EntityBeanIntercept> missed() {
+      return missed;
+    }
   }
 }

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

@@ -18,7 +18,8 @@ import java.text.MessageFormat;
 import java.util.List;
 import java.util.Set;
 
-import static java.lang.System.Logger.Level.*;
+import static java.lang.System.Logger.Level.DEBUG;
+import static java.lang.System.Logger.Level.ERROR;
 
 /**
  * Helper to handle lazy loading and refreshing of beans.
@@ -125,23 +126,26 @@ final class DefaultBeanLoader {
    * Load a batch of beans for +query or +lazy loading.
    */
   void loadBean(LoadBeanRequest loadRequest) {
-    Set<EntityBeanIntercept> batch = loadRequest.batch();
+    final Set<EntityBeanIntercept> batch = loadRequest.batch();
     if (batch.isEmpty()) {
       throw new RuntimeException("Nothing in batch?");
     }
 
-    List<Object> idList = loadRequest.getIdList();
-    if (idList.isEmpty()) {
-      // everything was loaded from cache
+    final List<Object> ids = loadRequest.ids();
+    if (ids.isEmpty()) {
+      // this should never happen given the batch is not empty
+      CoreLog.internal.log(ERROR, "No Ids when loading Batch buffer");
       return;
     }
 
-    SpiQuery<?> query = server.createQuery(loadRequest.beanType());
-    loadRequest.configureQuery(query, idList);
+    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)) {
-      String msg = MessageFormat.format("Loaded bean marked as deleted for {0} missedIds:{1} loadedIds:{2} sql:{3} list:{4}", loadRequest.beanType(), result.missedIds(), result.loadedIds(), query.getGeneratedSql(), list);
+      CoreLog.markedAsDeleted.log(DEBUG, "Loaded bean batch {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"));
     }
   }

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

@@ -125,6 +125,11 @@ final class DLoadBeanContext extends DLoadBaseContext implements LoadBeanContext
       this.batch = new HashSet<>(Math.max((int) (batchSize/.75f) + 1, 16));
     }
 
+    @Override
+    public String toString() {
+      return "LoadBuffer@" + hashCode();
+    }
+
     @Override
     public Lock lock() {
       bufferLock.lock();

ebean-test/src/test/java/org/tests/basic/TestManyOneInterface.java

@@ -1,7 +1,7 @@
 package org.tests.basic;
 
-import io.ebean.xtest.BaseTestCase;
 import io.ebean.DB;
+import io.ebean.xtest.BaseTestCase;
 import org.junit.jupiter.api.Test;
 import org.tests.model.basic.ResetBasicData;
 import org.tests.model.interfaces.Address;
@@ -9,23 +9,18 @@ import org.tests.model.interfaces.IAddress;
 import org.tests.model.interfaces.IPerson;
 import org.tests.model.interfaces.Person;
 
-public class TestManyOneInterface extends BaseTestCase {
+class TestManyOneInterface extends BaseTestCase {
 
   @Test
-  public void test() {
-
+  void test() {
     ResetBasicData.reset();
 
-    IAddress a = new Address("hello");
-
     IPerson p = new Person();
-
+    DB.save(p);
+    IAddress a = new Address("hello", p);
     p.setDefaultAddress(a);
 
     DB.save(a);
     DB.save(p);
-
-    //Assert.assertTrue();
-
   }
 }

ebean-test/src/test/java/org/tests/model/interfaces/Address.java

@@ -2,6 +2,7 @@ package org.tests.model.interfaces;
 
 import javax.persistence.Entity;
 import javax.persistence.Id;
+import javax.persistence.ManyToOne;
 import javax.persistence.Version;
 
 @Entity
@@ -13,10 +14,14 @@ public class Address implements IAddress {
   @Version
   private int version;
 
+  @ManyToOne(targetEntity=Person.class, optional=false)
+  private IPerson person;
+
   private String street;
 
-  public Address(String street) {
+  public Address(String street, IPerson person) {
     this.street = street;
+    this.person = person;
   }
 
   public long getOid() {

ebean-test/src/test/java/org/tests/model/interfaces/Person.java

@@ -1,9 +1,7 @@
 package org.tests.model.interfaces;
 
-import javax.persistence.Entity;
-import javax.persistence.Id;
-import javax.persistence.ManyToOne;
-import javax.persistence.Version;
+import javax.persistence.*;
+import java.util.List;
 
 @Entity
 public class Person implements IPerson {
@@ -13,6 +11,8 @@ public class Person implements IPerson {
   @Version
   private int version;
 
+  @OneToMany(targetEntity=Address.class)
+  private List<IAddress> addresses;
   @ManyToOne(targetEntity = Address.class)
   private IAddress defaultAddress;
 
@@ -42,4 +42,11 @@ public class Person implements IPerson {
     this.version = version;
   }
 
+  public List<IAddress> getAddresses() {
+    return addresses;
+  }
+
+  public void setAddresses(List<IAddress> addresses) {
+    this.addresses = addresses;
+  }
 }

ebean-test/src/test/java/org/tests/model/interfaces/TestTargetEntity.java

@@ -1,16 +1,17 @@
 package org.tests.model.interfaces;
 
-import io.ebean.xtest.BaseTestCase;
 import io.ebean.DB;
+import io.ebean.xtest.BaseTestCase;
 import org.junit.jupiter.api.Test;
 
+import java.util.List;
+
 import static org.assertj.core.api.Assertions.assertThat;
 
-public class TestTargetEntity extends BaseTestCase {
+class TestTargetEntity extends BaseTestCase {
 
   @Test
-  public void test() {
-
+  void test() {
     Person person = setup();
 
     Persona persona = new Persona("junk");
@@ -20,17 +21,48 @@ public class TestTargetEntity extends BaseTestCase {
     Persona found = DB.find(Persona.class, persona.getId());
     assertThat(found).isNotNull();
     assertThat(found.persona()).isEqualTo("junk");
-    assertThat(found.getPerson().getDefaultAddress().getStreet()).isEqualTo("street");
+    IPerson person1 = found.getPerson();
+    IAddress address = person1.getDefaultAddress();
+    assertThat(address.getStreet()).isEqualTo("street");
 
+    person1.setDefaultAddress(null);
+    DB.save(person1);
+    DB.delete(address);
     DB.delete(persona);
-    DB.delete(person);
-    DB.delete(person.getDefaultAddress());
+    DB.delete(person1);
+  }
+
+  @Test
+  void addresses() {
+    Person p0 = new Person();
+    Person p1 = new Person();
+    DB.saveAll(p0, p1);
+
+    Address address0 = new Address("a0", p0);
+    Address address1 = new Address("a1", p0);
+    Address address2 = new Address("a2", p1);
+    Address address3 = new Address("a3", p1);
+    DB.saveAll(address0, address1, address2, address3);
+
+    p0.setDefaultAddress(address0);
+    p1.setDefaultAddress(address2);
+    DB.saveAll(p0, p1);
+
+    List<Person> list = DB.find(Person.class).findList();
+    for (Person person : list) {
+      IAddress da0 = person.getDefaultAddress();
+      da0.getStreet();
+    }
+
+    list.get(0).getAddresses()
+      .size();
   }
 
   private Person setup() {
-    Address address = new Address("street");
-    DB.save(address);
     Person person = new Person();
+    DB.save(person);
+    Address address = new Address("street", person);
+    DB.save(address);
     person.setDefaultAddress(address);
     DB.save(person);
     return person;