Possible regression: Issues lazy loading deep relations that are soft-deleted

[patrickspensieri]

👉 keeping this open because these test cases back this issue

Issue

When upgrading from 12.12.3 to 13.8.0, we noticed deep relations were not being lazy-loaded when soft-deleted. See thread in Ebean ORM group.

• Tests in this PR pass when using version 13.8.0, but will fail with 12.12.3 indicating some change in behaviour between versions

Next steps

• Provide trace-level logs when running the tests with 13.8.0 and 12.12.3
• I can help identify which version introduced the change in behaviour (changed as of version 13.6.6)

Overview of results (2)

public class Usage {
  UUID id
  String name
  @ManyToOne
  Account account
}

public class Account {
  UUID id
  String name
  @OneToOne
  Environment environment
  @SoftDelete
  boolean deleted
}

public class Environment {
  UUID id
  String name
  @SoftDelete
  boolean deleted
}

1. Resolved: setIncludeSoftDeletes() does not fetch deep relations that are soft deleted:

• This is expected given the changes in #2750
• We can use .fetch() or .fetchLazy() to explicitly define how deep the .setIncludesSoftDelete() should go

// when: lazily fetching
List<UsageRaw> lazyUsage = server.find(UsageRaw.class)
  .setIncludeSoftDeletes()
  .findList();
// then: soft-deleted environments not loaded
assert(lazyUsage.size() == 2);
assert(lazyUsage.stream().filter(environmentLoaded()).count() == 1);

// when: eagerly fetching
List<UsageRaw> eagerUsage = server.find(UsageRaw.class)
  .setIncludeSoftDeletes()
  .fetch("serviceAccount.environment")
  .findList();
// then: soft-deleted environments are loaded
assert(eagerUsage.size() == 2);
assert(eagerUsage.stream().allMatch(environmentLoaded()));

2. Bug: Queries with several fetchLazy do not return complete path

• See issue in ebean repo.
• The following is a possible issue outlined fully in this test
• The test also documents possible workarounds

// demonstrates new behaviour in 13.6.6
// when: lazy fetching serviceAccount AND serviceAccount.environment
List<UsageRaw> lazyUsageMultiplePaths = server.find(UsageRaw.class)
  .setIncludeSoftDeletes()
  .fetchLazy("serviceAccount")
  .fetchLazy("serviceAccount.environment")
  .findList();
// then: soft-deleted environments are NOT loaded (not the case before 13.6.6)
assert(lazyUsageMultiplePaths.size() == 2);
assert(lazyUsageMultiplePaths.stream().allMatch(accountLoaded()));
assert(lazyUsageMultiplePaths.stream().filter(environmentLoaded()).count() == 1);

// demonstrates workaround, use single path, all required properties are loaded
// when: lazy fetching serviceAccount.environment
List<UsageRaw> lazyUsageSinglePath = server.find(UsageRaw.class)
  .setIncludeSoftDeletes()
  .fetchLazy("serviceAccount.environment")
  .findList();
// then: soft-deleted environments loaded
assert(lazyUsageSinglePath.size() == 2);
assert(lazyUsageSinglePath.stream().allMatch(accountLoaded()));
assert(lazyUsageSinglePath.stream().allMatch(environmentLoaded()));

[patrickspensieri]

When running 12.12.3, soft-deleted environments are all loaded

[patrickspensieri]

Relevant trace-level logs with 13.8.0

14:08:24.973 [main] INFO  io.ebean - ebean version: 13.8.0
14:08:25.036 [main] DEBUG io.ebean.test - automatic testing config - with ebean.test.platform:mysql name:db environmentDb:null
...
14:08:26.935 [main] TRACE io.ebean.BackgroundExecutor - Queued io.ebeaninternal.server.transaction.PostCommitProcessing$$Lambda$388/0x0000000800f3d748@790132f7
14:08:26.935 [ebean-db1] TRACE io.ebean.BackgroundExecutor - Start io.ebeaninternal.server.transaction.PostCommitProcessing$$Lambda$388/0x0000000800f3d748@790132f7 (delay time 149 us)
14:08:26.935 [ebean-db1] TRACE io.ebean.BackgroundExecutor - Stop io.ebeaninternal.server.transaction.PostCommitProcessing$$Lambda$388/0x0000000800f3d748@790132f7 (exec time 85 us)
14:08:26.982 [main] DEBUG io.ebean.SQL - txn[1007] select t0.id, t0.name, t0.service_account_id from usage_raw t0; --bind() --micros(2786)
14:08:26.985 [main] DEBUG io.ebean.SUM - txn[1007] FindMany type[UsageRaw] origin[CPGDwA.A.A] exeMicros[6880] rows[2] predicates[] bind[]
14:08:27.000 [main] DEBUG io.ebean.SQL - txn[1008] select t0.id, t0.name, t0.deleted, t0.environment_id from service_account t0 where t0.id in (?,?,?,?,?); --bind(Array[5]={fa11cfac-6506-441b-a3b8-40960ffca274,9ba551d0-b1ff-4081-be22-4d8078badd48,...}) --micros(4869)
14:08:27.001 [main] DEBUG io.ebean.SUM - txn[1008] FindMany mode[+lazy] type[ServiceAccount] origin[CPGDwA.A.A] lazyLoadProp[name] load[serviceAccount] exeMicros[5943] rows[2] predicates[t0.id in (?,?,?,?,?)] bind[Array[5]={fa11cfac-6506-441b-a3b8-40960ffca274,9ba551d0-b1ff-4081-be22-4d8078badd48,...}]
14:08:27.006 [main] DEBUG io.ebean.SQL - txn[1009] select t0.id, t0.name, t0.deleted from environment t0 where t0.id in (?,?,?,?,?) and t0.deleted = 0; --bind(Array[5]={5df80ffe-c6f7-4adf-85cd-075ed460d9c3,2e7203c3-9084-4038-860e-68d1d70c6982,...}) --micros(2136)
14:08:27.006 [main] DEBUG io.ebean.SUM - txn[1009] FindMany mode[+lazy] type[Environment] origin[CPGDwA.A.A] lazyLoadProp[name] load[serviceAccount.environment] exeMicros[2489] rows[1] predicates[t0.id in (?,?,?,?,?)] bind[Array[5]={5df80ffe-c6f7-4adf-85cd-075ed460d9c3,2e7203c3-9084-4038-860e-68d1d70c6982,...}]
14:08:27.015 [main] DEBUG io.ebean.SQL - txn[1010] select t0.id, t0.name, t1.id, t2.id, t2.name, t2.deleted from usage_raw t0 left join service_account t1 on t1.id = t0.service_account_id left join environment t2 on t2.id = t1.environment_id; --bind() --micros(3707)
14:08:27.016 [main] DEBUG io.ebean.SUM - txn[1010] FindMany type[UsageRaw] origin[CPGDwA.A.A] exeMicros[4393] rows[2] predicates[] bind[]
14:08:27.020 [main] DEBUG io.ebean.SQL - txn[1011] select t0.id, t0.name, t0.deleted, t0.environment_id from service_account t0 where t0.id in (?,?,?,?,?); --bind(Array[5]={9ba551d0-b1ff-4081-be22-4d8078badd48,fa11cfac-6506-441b-a3b8-40960ffca274,...}) --micros(1576)
14:08:27.020 [main] DEBUG io.ebean.SUM - txn[1011] FindMany mode[+lazy] type[ServiceAccount] origin[CPGDwA.A.A] lazyLoadProp[name] load[serviceAccount] exeMicros[1912] rows[2] predicates[t0.id in (?,?,?,?,?)] bind[Array[5]={9ba551d0-b1ff-4081-be22-4d8078badd48,fa11cfac-6506-441b-a3b8-40960ffca274,...}]
14:08:27.034 [EbeanHook] DEBUG io.ebean - Ebean shutting down
...

And trace-level logs with 12.12.3

14:06:01.526 [main] INFO  io.ebean - ebean version: 12.12.3
14:06:01.549 [main] DEBUG io.ebean.test - automatic testing config - with ebean.test.platform:mysql environment db:null name:db
...
14:06:02.754 [main] DEBUG io.ebean.SQL - txn[1007] select t0.id, t0.name, t0.service_account_id from usage_raw t0; --bind() --micros(4341)
14:06:02.757 [main] DEBUG io.ebean.SUM - txn[1007] FindMany type[UsageRaw] origin[CPGDwA.A.A] exeMicros[6663] rows[2] predicates[] bind[]
14:06:02.769 [main] DEBUG io.ebean.SQL - txn[1008] select t0.id, t0.name, t0.deleted, t0.environment_id from service_account t0 where t0.id in (?,?,?,?,?); --bind(Array[5]={64010ab7-abf0-44b8-a4f8-74b33eb21186,d850d5ee-7116-425e-907d-f44ee79e0090,...}) --micros(4252)
14:06:02.770 [main] DEBUG io.ebean.SUM - txn[1008] FindMany mode[+lazy] type[ServiceAccount] origin[CPGDwA.A.A] lazyLoadProp[name] load[serviceAccount] exeMicros[4977] rows[2] predicates[t0.id in (?,?,?,?,?)] bind[Array[5]={64010ab7-abf0-44b8-a4f8-74b33eb21186,d850d5ee-7116-425e-907d-f44ee79e0090,...}]
14:06:02.774 [main] DEBUG io.ebean.SQL - txn[1009] select t0.id, t0.name, t0.deleted from environment t0 where t0.id in (?,?,?,?,?); --bind(Array[5]={6b293c27-9ea6-4a76-8f9c-213a12c00beb,c82d50f5-564d-47d6-b142-b35db784055a,...}) --micros(2090)
14:06:02.775 [main] DEBUG io.ebean.SUM - txn[1009] FindMany mode[+lazy] type[Environment] origin[CPGDwA.A.A] lazyLoadProp[name] load[serviceAccount.environment] exeMicros[2397] rows[2] predicates[t0.id in (?,?,?,?,?)] bind[Array[5]={6b293c27-9ea6-4a76-8f9c-213a12c00beb,c82d50f5-564d-47d6-b142-b35db784055a,...}]
14:06:02.787 [main] DEBUG io.ebean.SQL - txn[1010] select t0.id, t0.name, t1.id, t2.id, t2.name, t2.deleted from usage_raw t0 left join service_account t1 on t1.id = t0.service_account_id left join environment t2 on t2.id = t1.environment_id; --bind() --micros(7888)
14:06:02.789 [main] DEBUG io.ebean.SUM - txn[1010] FindMany type[UsageRaw] origin[CPGDwA.A.A] exeMicros[10325] rows[2] predicates[] bind[]
14:06:02.795 [main] DEBUG io.ebean.SQL - txn[1011] select t0.id, t0.name, t0.deleted, t0.environment_id from service_account t0 where t0.id in (?,?,?,?,?); --bind(Array[5]={64010ab7-abf0-44b8-a4f8-74b33eb21186,d850d5ee-7116-425e-907d-f44ee79e0090,...}) --micros(2868)
14:06:02.795 [main] DEBUG io.ebean.SUM - txn[1011] FindMany mode[+lazy] type[ServiceAccount] origin[CPGDwA.A.A] lazyLoadProp[name] load[serviceAccount] exeMicros[3272] rows[2] predicates[t0.id in (?,?,?,?,?)] bind[Array[5]={64010ab7-abf0-44b8-a4f8-74b33eb21186,d850d5ee-7116-425e-907d-f44ee79e0090,...}]
14:06:02.807 [EbeanHook] DEBUG io.ebean - Ebean shutting down
...

[patrickspensieri]

Changes in lazy loading soft deleted relations occur as of v13.6.6, might be expected given #2750: Stateless update populates OneToMany with softdeleted records during serializing

[patrickspensieri]

Closing this since

• API change causing deep relations to soft-deleted entities is intended
• Opened an issue for queries no longer retrieving deep soft-deleted paths when fetchLazy() are chained

[patrickspensieri]

Actually, I'll leave it open because the bug refers to this PR for unit test proving the issue