Skip to content

EF Core query resolution breaks depending on entity class name when enabling split queries #24777

New issue
New issue
Closed
Closed
EF Core query resolution breaks depending on entity class name when enabling split queries#24777

Description

@TAGC

TAGC
openedon Apr 27, 2021

EF Core doesn't seem to like the second half of the alphabet. I've spent 13 hours debugging an issue with my application and this is one of the strangest issues I've come across.

Consider a hierarchy of entities like this:

Entity hierarchy

In an application, I would model this in the DbContext by configuring Root to own MiddleA and MiddleB, and MiddleA to own a collection of Leaf.

Under certain conditions, changing the name of MiddleA affects the query resolution logic of EF Core. This issue is only reproducible when:

  • Query splitting behaviour is set to "split query" rather than "single query".
  • The entity hierarchy includes an entity at the same level within the composition graph as MiddleA (i.e. MiddleB in this case).

Code

To reproduce this issue, create a new C# console application targeting .NET 5 and include the following code:

Domain

public class Entity
{
    public int Id { get; init; }
}

public class Root : Entity
{
    public MiddleA MiddleA { get; init; }
    public MiddleB MiddleB { get; init; }
}

public class MiddleA : Entity
{
    public int RootId { get; init; }
    public List<Leaf> Leaves { get; init; }
}

public class MiddleB : Entity
{
    public int RootId { get; init; }
    public bool Enabled { get; init; }
}

public class Leaf
{
    public int MiddleAId { get; init; }
    public int UnitThreshold { get; init; }
}

Context

public class Context : DbContext
{
    // Replace with appropriate connection string.
    private const string ConnectionString = "...";

    // Alternate between "SplitQuery" and "SingleQuery" to demonstrate issue.
    // Issue only reproducible when set to "SplitQuery".
    private const QuerySplittingBehavior ContextQuerySplittingBehavior = QuerySplittingBehavior.SplitQuery;

    // Alternate between "true" and "false" to demonstrate issue.
    // Issue only reproducible when set to "false".
    private const bool IgnoreMiddleB = false;

    public DbSet<Root> Roots { get; private init; } = null!;

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        optionsBuilder.UseSqlServer(ConnectionString, o =>
        {
            o.UseQuerySplittingBehavior(ContextQuerySplittingBehavior);
        });

        optionsBuilder.EnableDetailedErrors();
        optionsBuilder.EnableSensitiveDataLogging();
        //optionsBuilder.LogTo(Console.WriteLine);
    }

    protected override void OnModelCreating(ModelBuilder modelBuilder)
    {
        modelBuilder.Entity<Root>(ConfigureRoot);
    }

    private static void ConfigureRoot(EntityTypeBuilder<Root> builder)
    {
        builder.ToTable(nameof(Root));
        builder.HasKey(x => x.Id);
        builder.OwnsOne(x => x.MiddleA, ConfigureMiddleA);

        if (IgnoreMiddleB)
        {
            builder.Ignore(x => x.MiddleB);
        }
        else
        {
            builder.OwnsOne(x => x.MiddleB, ConfigureMiddleB);
        }

        builder.HasData(
            new Root {Id = 1},
            new Root {Id = 2},
            new Root {Id = 3});
    }

    private static void ConfigureMiddleA(OwnedNavigationBuilder<Root, MiddleA> builder)
    {
        builder.ToTable(nameof(MiddleA));
        builder.HasKey(x => x.Id);
        builder.WithOwner();
        builder.OwnsMany(x => x.Leaves, ConfigureLeaf);
        builder.HasData(
            new MiddleA {Id = 1, RootId = 1},
            new MiddleA {Id = 2, RootId = 2},
            new MiddleA {Id = 3, RootId = 3});
    }

    private static void ConfigureMiddleB(OwnedNavigationBuilder<Root, MiddleB> builder)
    {
        builder.ToTable(nameof(MiddleB));
        builder.HasKey(x => x.Id);
        builder.WithOwner();
        builder.HasData(
            new MiddleB {Id = 1, RootId = 1, Enabled = true},
            new MiddleB {Id = 2, RootId = 3, Enabled = true});
    }

    private static void ConfigureLeaf(OwnedNavigationBuilder<MiddleA, Leaf> builder)
    {
        builder.ToTable(nameof(Leaf));
        builder.HasKey(x => new {ProductCommissionRulesetId = x.MiddleAId, x.UnitThreshold});
        builder.WithOwner();
        builder.HasData(
            new Leaf {MiddleAId = 1, UnitThreshold = 1},
            new Leaf {MiddleAId = 3, UnitThreshold = 1},
            new Leaf {MiddleAId = 3, UnitThreshold = 15});
    }
}

Program

using System;
using EfCoreOwnershipIssue;

await using var context = new Context();

await context.Database.EnsureDeletedAsync();
await context.Database.EnsureCreatedAsync();

var root1 = await context.Roots.FindAsync(1);
var root3 = await context.Roots.FindAsync(3);

var root1Leaves = root1.MiddleA.Leaves.Count;
var root3Leaves = root3.MiddleA.Leaves.Count;

Console.WriteLine("Root 1 leaves: " + root1Leaves); // Expected output: 1
Console.WriteLine("Root 3 leaves: " + root3Leaves); // Expected output: 2

Expected Behaviour

Running this program should create a new database, apply the configured schema, populate the tables with the seed data and consistently return this output in the console window:

Root 1 leaves: 1
Root 3 leaves: 2

This behaviour should remain consistent regardless of the type of query splitting behaviour used or the names of the entity types.

Actual Behaviour

When configuring the application to use "split query" behaviour, the class name of the entity that I label MiddleA affects whether EF Core correctly queries the database or not. In some cases, the query logic works and the console output is as above. In other cases, EF Core doesn't query the Leaf entities associated with the MiddleA entity of Root {Id=3}, generating this output instead:

Root 1 leaves: 1
Root 3 leaves: 0

For example, renaming the MiddleA class to Mommission and the foreign key property on Leaf to MommissionId causes the query logic to break, but calling it Lommission (LommissionId) works.

Similarly, MiddleA (MiddleAId) works but ModdleA (ModdleAId) causes it to break.

It's unclear what the pattern is but there seems to be some sort of cut-off at the L/M point in the alphabet. Class names like Dommission, Fommission, etc. work whereas Mommission, Nommission, Zommission fail. The pattern holds if we truncate letters from the end of the class name (Dommissio works, Zommissio fails). This isn't a strict cut-off since, since again MiddleA works fine even though it begins with M. For any given name, the behaviour is consistent; the query logic will always succeed when the entity is called Lommission and always fail when it's called Mommission.

Setting the application to use "single query" splitting behaviour should consistently show the output to be 2 instead of 0, regardless of entity type names.

Configuring the DbContext to ignore the Root.MiddleB property should consistently show the output to be 2 instead of 0, regardless of entity type names.

Verbose Output

In both cases below, the console output has been generated with EnsureDeletedAsync() \ EnsureCreatedAsync() commented out to reduce output verbosity.

When configuring the application with a "good" entity type name (e.g. MiddleA), the following EF Core output is logged to the console window:

warn: 27/04/2021 15:09:19.894 CoreEventId.SensitiveDataLoggingEnabledWarning[10400] (Microsoft.EntityFrameworkCore.Infrastructure)
      Sensitive data logging is enabled. Log entries and exception messages may include sensitive application data; this mode should only be enabled during development.
info: 27/04/2021 15:09:20.090 CoreEventId.ContextInitialized[10403] (Microsoft.EntityFrameworkCore.Infrastructure)
      Entity Framework Core 5.0.5 initialized 'Context' using provider 'Microsoft.EntityFrameworkCore.SqlServer' with options: QuerySplittingBehavior=SplitQuery SensitiveDataLoggingEnabled DetailedErrorsEnabled
dbug: 27/04/2021 15:09:20.202 CoreEventId.QueryCompilationStarting[10111] (Microsoft.EntityFrameworkCore.Query)
      Compiling query expression:
      'DbSet<Root>()
          .FirstOrDefault(e => EF.Property<int>(e, "Id") == __p_0)'
dbug: 27/04/2021 15:09:20.256 CoreEventId.NavigationBaseIncluded[10112] (Microsoft.EntityFrameworkCore.Query)
      Including navigation: 'Root.MiddleA'.
dbug: 27/04/2021 15:09:20.257 CoreEventId.NavigationBaseIncluded[10112] (Microsoft.EntityFrameworkCore.Query)
      Including navigation: 'MiddleA.Leaves'.
dbug: 27/04/2021 15:09:20.258 CoreEventId.NavigationBaseIncluded[10112] (Microsoft.EntityFrameworkCore.Query)
      Including navigation: 'Root.MiddleB'.
warn: 27/04/2021 15:09:20.315 CoreEventId.RowLimitingOperationWithoutOrderByWarning[10102] (Microsoft.EntityFrameworkCore.Query)
      The query uses a row limiting operator ('Skip'/'Take') without an 'OrderBy' operator. This may lead to unpredictable results.
dbug: 27/04/2021 15:09:20.438 CoreEventId.QueryExecutionPlanned[10107] (Microsoft.EntityFrameworkCore.Query)
      Generated query execution expression:
      'queryContext => ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync<Root>(
          asyncEnumerable: new SplitQueryingEnumerable<Root>(
              (RelationalQueryContext)queryContext,
              RelationalCommandCache.SelectExpression(
                  Projection Mapping:
                  SELECT t.Id, t.Id0, t.RootId, t.Id1, t.Enabled, t.RootId0
                  FROM Projection Mapping:
                  (
                      SELECT TOP(1) r.Id, m.Id AS Id0, m.RootId, m0.Id AS Id1, m0.Enabled, m0.RootId AS RootId0
                      FROM Root AS r
                      LEFT JOIN MiddleA AS m ON r.Id == m.RootId
                      LEFT JOIN MiddleB AS m0 ON r.Id == m0.RootId
                      WHERE r.Id == @__p_0
                  ) AS t
                  ORDER BY t.Id ASC, t.Id0 ASC),
              Func<QueryContext, DbDataReader, ResultContext, SplitQueryResultCoordinator, Root>,
              null,
              Func<QueryContext, IExecutionStrategy, SplitQueryResultCoordinator, Task>,
              EfCoreOwnershipIssue.Context,
              False,
              True
          ),
          cancellationToken: queryContext.CancellationToken)'
dbug: 27/04/2021 15:09:20.521 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 27/04/2021 15:09:20.526 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (47ms).
dbug: 27/04/2021 15:09:20.551 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:09:20.900 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:09:20.908 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT [t].[Id], [t].[Id0], [t].[RootId], [t].[Id1], [t].[Enabled], [t].[RootId0]
      FROM (
          SELECT TOP(1) [r].[Id], [m].[Id] AS [Id0], [m].[RootId], [m0].[Id] AS [Id1], [m0].[Enabled], [m0].[RootId] AS [RootId0]
          FROM [Root] AS [r]
          LEFT JOIN [MiddleA] AS [m] ON [r].[Id] = [m].[RootId]
          LEFT JOIN [MiddleB] AS [m0] ON [r].[Id] = [m0].[RootId]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      ORDER BY [t].[Id], [t].[Id0]
info: 27/04/2021 15:09:20.964 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (59ms) [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT [t].[Id], [t].[Id0], [t].[RootId], [t].[Id1], [t].[Enabled], [t].[RootId0]
      FROM (
          SELECT TOP(1) [r].[Id], [m].[Id] AS [Id0], [m].[RootId], [m0].[Id] AS [Id1], [m0].[Enabled], [m0].[RootId] AS [RootId0]
          FROM [Root] AS [r]
          LEFT JOIN [MiddleA] AS [m] ON [r].[Id] = [m].[RootId]
          LEFT JOIN [MiddleB] AS [m0] ON [r].[Id] = [m0].[RootId]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      ORDER BY [t].[Id], [t].[Id0]
dbug: 27/04/2021 15:09:21.013 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'Root' entity with key '{Id: 1}'.
dbug: 27/04/2021 15:09:21.027 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'MiddleA' entity with key '{Id: 1}'.
dbug: 27/04/2021 15:09:21.040 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'MiddleB' entity with key '{Id: 1}'.
dbug: 27/04/2021 15:09:21.055 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 27/04/2021 15:09:21.055 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 27/04/2021 15:09:21.066 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT [l].[MiddleAId], [l].[UnitThreshold], [t].[Id], [m].[Id]
      FROM (
          SELECT TOP(1) [r].[Id]
          FROM [Root] AS [r]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      LEFT JOIN [MiddleA] AS [m] ON [t].[Id] = [m].[RootId]
      INNER JOIN [Leaf] AS [l] ON [m].[Id] = [l].[MiddleAId]
      ORDER BY [t].[Id], [m].[Id]
info: 27/04/2021 15:09:21.085 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (19ms) [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT [l].[MiddleAId], [l].[UnitThreshold], [t].[Id], [m].[Id]
      FROM (
          SELECT TOP(1) [r].[Id]
          FROM [Root] AS [r]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      LEFT JOIN [MiddleA] AS [m] ON [t].[Id] = [m].[RootId]
      INNER JOIN [Leaf] AS [l] ON [m].[Id] = [l].[MiddleAId]
      ORDER BY [t].[Id], [m].[Id]
dbug: 27/04/2021 15:09:21.111 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'Leaf' entity with key '{MiddleAId: 1, UnitThreshold: 1}'.
dbug: 27/04/2021 15:09:21.127 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 27/04/2021 15:09:21.131 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 27/04/2021 15:09:21.133 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:09:21.146 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:09:21.148 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 27/04/2021 15:09:21.149 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 27/04/2021 15:09:21.149 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:09:21.151 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:09:21.151 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='3'], CommandType='Text', CommandTimeout='30']
      SELECT [t].[Id], [t].[Id0], [t].[RootId], [t].[Id1], [t].[Enabled], [t].[RootId0]
      FROM (
          SELECT TOP(1) [r].[Id], [m].[Id] AS [Id0], [m].[RootId], [m0].[Id] AS [Id1], [m0].[Enabled], [m0].[RootId] AS [RootId0]
          FROM [Root] AS [r]
          LEFT JOIN [MiddleA] AS [m] ON [r].[Id] = [m].[RootId]
          LEFT JOIN [MiddleB] AS [m0] ON [r].[Id] = [m0].[RootId]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      ORDER BY [t].[Id], [t].[Id0]
info: 27/04/2021 15:09:21.172 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (21ms) [Parameters=[@__p_0='3'], CommandType='Text', CommandTimeout='30']
      SELECT [t].[Id], [t].[Id0], [t].[RootId], [t].[Id1], [t].[Enabled], [t].[RootId0]
      FROM (
          SELECT TOP(1) [r].[Id], [m].[Id] AS [Id0], [m].[RootId], [m0].[Id] AS [Id1], [m0].[Enabled], [m0].[RootId] AS [RootId0]
          FROM [Root] AS [r]
          LEFT JOIN [MiddleA] AS [m] ON [r].[Id] = [m].[RootId]
          LEFT JOIN [MiddleB] AS [m0] ON [r].[Id] = [m0].[RootId]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      ORDER BY [t].[Id], [t].[Id0]
dbug: 27/04/2021 15:09:21.174 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'Root' entity with key '{Id: 3}'.
dbug: 27/04/2021 15:09:21.174 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'MiddleA' entity with key '{Id: 3}'.
dbug: 27/04/2021 15:09:21.175 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'MiddleB' entity with key '{Id: 2}'.
dbug: 27/04/2021 15:09:21.175 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 27/04/2021 15:09:21.176 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 27/04/2021 15:09:21.176 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='3'], CommandType='Text', CommandTimeout='30']
      SELECT [l].[MiddleAId], [l].[UnitThreshold], [t].[Id], [m].[Id]
      FROM (
          SELECT TOP(1) [r].[Id]
          FROM [Root] AS [r]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      LEFT JOIN [MiddleA] AS [m] ON [t].[Id] = [m].[RootId]
      INNER JOIN [Leaf] AS [l] ON [m].[Id] = [l].[MiddleAId]
      ORDER BY [t].[Id], [m].[Id]
info: 27/04/2021 15:09:21.191 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (15ms) [Parameters=[@__p_0='3'], CommandType='Text', CommandTimeout='30']
      SELECT [l].[MiddleAId], [l].[UnitThreshold], [t].[Id], [m].[Id]
      FROM (
          SELECT TOP(1) [r].[Id]
          FROM [Root] AS [r]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      LEFT JOIN [MiddleA] AS [m] ON [t].[Id] = [m].[RootId]
      INNER JOIN [Leaf] AS [l] ON [m].[Id] = [l].[MiddleAId]
      ORDER BY [t].[Id], [m].[Id]
dbug: 27/04/2021 15:09:21.195 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'Leaf' entity with key '{MiddleAId: 3, UnitThreshold: 1}'.
dbug: 27/04/2021 15:09:21.199 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'Leaf' entity with key '{MiddleAId: 3, UnitThreshold: 15}'.
dbug: 27/04/2021 15:09:21.200 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 27/04/2021 15:09:21.200 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 27/04/2021 15:09:21.201 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:09:21.201 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
Root 1 leaves: 1
Root 3 leaves: 2
dbug: 27/04/2021 15:09:21.206 CoreEventId.ContextDisposed[10407] (Microsoft.EntityFrameworkCore.Infrastructure)
      'Context' disposed.

C:\Projects\EfCoreOwnershipIssue\bin\Debug\net5.0\EfCoreOwnershipIssue.exe (process 17660) exited with code 0.
To automatically close the console when debugging stops, enable Tools->Options->Debugging->Automatically close the console when debugging stops.
Press any key to close this window . . .

When configuring the application with a "bad" entity type name (e.g. ModdleA), the following EF Core output is logged to the console window:

warn: 27/04/2021 15:11:00.051 CoreEventId.SensitiveDataLoggingEnabledWarning[10400] (Microsoft.EntityFrameworkCore.Infrastructure)
      Sensitive data logging is enabled. Log entries and exception messages may include sensitive application data; this mode should only be enabled during development.
info: 27/04/2021 15:11:00.284 CoreEventId.ContextInitialized[10403] (Microsoft.EntityFrameworkCore.Infrastructure)
      Entity Framework Core 5.0.5 initialized 'Context' using provider 'Microsoft.EntityFrameworkCore.SqlServer' with options: QuerySplittingBehavior=SplitQuery SensitiveDataLoggingEnabled DetailedErrorsEnabled
dbug: 27/04/2021 15:11:00.401 CoreEventId.QueryCompilationStarting[10111] (Microsoft.EntityFrameworkCore.Query)
      Compiling query expression:
      'DbSet<Root>()
          .FirstOrDefault(e => EF.Property<int>(e, "Id") == __p_0)'
dbug: 27/04/2021 15:11:00.471 CoreEventId.NavigationBaseIncluded[10112] (Microsoft.EntityFrameworkCore.Query)
      Including navigation: 'Root.MiddleB'.
dbug: 27/04/2021 15:11:00.471 CoreEventId.NavigationBaseIncluded[10112] (Microsoft.EntityFrameworkCore.Query)
      Including navigation: 'Root.ModdleA'.
dbug: 27/04/2021 15:11:00.473 CoreEventId.NavigationBaseIncluded[10112] (Microsoft.EntityFrameworkCore.Query)
      Including navigation: 'ModdleA.Leaves'.
warn: 27/04/2021 15:11:00.533 CoreEventId.RowLimitingOperationWithoutOrderByWarning[10102] (Microsoft.EntityFrameworkCore.Query)
      The query uses a row limiting operator ('Skip'/'Take') without an 'OrderBy' operator. This may lead to unpredictable results.
dbug: 27/04/2021 15:11:00.662 CoreEventId.QueryExecutionPlanned[10107] (Microsoft.EntityFrameworkCore.Query)
      Generated query execution expression:
      'queryContext => ShapedQueryCompilingExpressionVisitor.SingleOrDefaultAsync<Root>(
          asyncEnumerable: new SplitQueryingEnumerable<Root>(
              (RelationalQueryContext)queryContext,
              RelationalCommandCache.SelectExpression(
                  Projection Mapping:
                  SELECT t.Id, t.Id0, t.Enabled, t.RootId, t.Id1, t.RootId0
                  FROM Projection Mapping:
                  (
                      SELECT TOP(1) r.Id, m.Id AS Id0, m.Enabled, m.RootId, m0.Id AS Id1, m0.RootId AS RootId0
                      FROM Root AS r
                      LEFT JOIN MiddleB AS m ON r.Id == m.RootId
                      LEFT JOIN ModdleA AS m0 ON r.Id == m0.RootId
                      WHERE r.Id == @__p_0
                  ) AS t
                  ORDER BY t.Id ASC, t.Id0 ASC),
              Func<QueryContext, DbDataReader, ResultContext, SplitQueryResultCoordinator, Root>,
              null,
              Func<QueryContext, IExecutionStrategy, SplitQueryResultCoordinator, Task>,
              EfCoreOwnershipIssue.Context,
              False,
              True
          ),
          cancellationToken: queryContext.CancellationToken)'
dbug: 27/04/2021 15:11:00.744 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 27/04/2021 15:11:00.749 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (45ms).
dbug: 27/04/2021 15:11:00.775 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:11:01.133 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:11:01.142 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT [t].[Id], [t].[Id0], [t].[Enabled], [t].[RootId], [t].[Id1], [t].[RootId0]
      FROM (
          SELECT TOP(1) [r].[Id], [m].[Id] AS [Id0], [m].[Enabled], [m].[RootId], [m0].[Id] AS [Id1], [m0].[RootId] AS [RootId0]
          FROM [Root] AS [r]
          LEFT JOIN [MiddleB] AS [m] ON [r].[Id] = [m].[RootId]
          LEFT JOIN [ModdleA] AS [m0] ON [r].[Id] = [m0].[RootId]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      ORDER BY [t].[Id], [t].[Id0]
info: 27/04/2021 15:11:01.198 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (60ms) [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT [t].[Id], [t].[Id0], [t].[Enabled], [t].[RootId], [t].[Id1], [t].[RootId0]
      FROM (
          SELECT TOP(1) [r].[Id], [m].[Id] AS [Id0], [m].[Enabled], [m].[RootId], [m0].[Id] AS [Id1], [m0].[RootId] AS [RootId0]
          FROM [Root] AS [r]
          LEFT JOIN [MiddleB] AS [m] ON [r].[Id] = [m].[RootId]
          LEFT JOIN [ModdleA] AS [m0] ON [r].[Id] = [m0].[RootId]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      ORDER BY [t].[Id], [t].[Id0]
dbug: 27/04/2021 15:11:01.244 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'Root' entity with key '{Id: 1}'.
dbug: 27/04/2021 15:11:01.256 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'MiddleB' entity with key '{Id: 1}'.
dbug: 27/04/2021 15:11:01.273 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'ModdleA' entity with key '{Id: 1}'.
dbug: 27/04/2021 15:11:01.284 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 27/04/2021 15:11:01.284 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 27/04/2021 15:11:01.295 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT [l].[ModdleAId], [l].[UnitThreshold], [t].[Id], [m].[Id]
      FROM (
          SELECT TOP(1) [r].[Id]
          FROM [Root] AS [r]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      LEFT JOIN [ModdleA] AS [m] ON [t].[Id] = [m].[RootId]
      INNER JOIN [Leaf] AS [l] ON [m].[Id] = [l].[ModdleAId]
      ORDER BY [t].[Id], [m].[Id]
info: 27/04/2021 15:11:01.319 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (25ms) [Parameters=[@__p_0='1'], CommandType='Text', CommandTimeout='30']
      SELECT [l].[ModdleAId], [l].[UnitThreshold], [t].[Id], [m].[Id]
      FROM (
          SELECT TOP(1) [r].[Id]
          FROM [Root] AS [r]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      LEFT JOIN [ModdleA] AS [m] ON [t].[Id] = [m].[RootId]
      INNER JOIN [Leaf] AS [l] ON [m].[Id] = [l].[ModdleAId]
      ORDER BY [t].[Id], [m].[Id]
dbug: 27/04/2021 15:11:01.338 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'Leaf' entity with key '{ModdleAId: 1, UnitThreshold: 1}'.
dbug: 27/04/2021 15:11:01.349 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 27/04/2021 15:11:01.352 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 27/04/2021 15:11:01.362 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:11:01.369 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:11:01.375 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 27/04/2021 15:11:01.375 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 27/04/2021 15:11:01.376 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opening connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:11:01.377 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection)
      Opened connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:11:01.377 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='3'], CommandType='Text', CommandTimeout='30']
      SELECT [t].[Id], [t].[Id0], [t].[Enabled], [t].[RootId], [t].[Id1], [t].[RootId0]
      FROM (
          SELECT TOP(1) [r].[Id], [m].[Id] AS [Id0], [m].[Enabled], [m].[RootId], [m0].[Id] AS [Id1], [m0].[RootId] AS [RootId0]
          FROM [Root] AS [r]
          LEFT JOIN [MiddleB] AS [m] ON [r].[Id] = [m].[RootId]
          LEFT JOIN [ModdleA] AS [m0] ON [r].[Id] = [m0].[RootId]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      ORDER BY [t].[Id], [t].[Id0]
info: 27/04/2021 15:11:01.393 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (15ms) [Parameters=[@__p_0='3'], CommandType='Text', CommandTimeout='30']
      SELECT [t].[Id], [t].[Id0], [t].[Enabled], [t].[RootId], [t].[Id1], [t].[RootId0]
      FROM (
          SELECT TOP(1) [r].[Id], [m].[Id] AS [Id0], [m].[Enabled], [m].[RootId], [m0].[Id] AS [Id1], [m0].[RootId] AS [RootId0]
          FROM [Root] AS [r]
          LEFT JOIN [MiddleB] AS [m] ON [r].[Id] = [m].[RootId]
          LEFT JOIN [ModdleA] AS [m0] ON [r].[Id] = [m0].[RootId]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      ORDER BY [t].[Id], [t].[Id0]
dbug: 27/04/2021 15:11:01.396 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'Root' entity with key '{Id: 3}'.
dbug: 27/04/2021 15:11:01.397 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'MiddleB' entity with key '{Id: 2}'.
dbug: 27/04/2021 15:11:01.401 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking)
      Context 'Context' started tracking 'ModdleA' entity with key '{Id: 3}'.
dbug: 27/04/2021 15:11:01.402 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command)
      Creating DbCommand for 'ExecuteReader'.
dbug: 27/04/2021 15:11:01.403 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command)
      Created DbCommand for 'ExecuteReader' (0ms).
dbug: 27/04/2021 15:11:01.403 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command)
      Executing DbCommand [Parameters=[@__p_0='3'], CommandType='Text', CommandTimeout='30']
      SELECT [l].[ModdleAId], [l].[UnitThreshold], [t].[Id], [m].[Id]
      FROM (
          SELECT TOP(1) [r].[Id]
          FROM [Root] AS [r]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      LEFT JOIN [ModdleA] AS [m] ON [t].[Id] = [m].[RootId]
      INNER JOIN [Leaf] AS [l] ON [m].[Id] = [l].[ModdleAId]
      ORDER BY [t].[Id], [m].[Id]
info: 27/04/2021 15:11:01.418 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (15ms) [Parameters=[@__p_0='3'], CommandType='Text', CommandTimeout='30']
      SELECT [l].[ModdleAId], [l].[UnitThreshold], [t].[Id], [m].[Id]
      FROM (
          SELECT TOP(1) [r].[Id]
          FROM [Root] AS [r]
          WHERE [r].[Id] = @__p_0
      ) AS [t]
      LEFT JOIN [ModdleA] AS [m] ON [t].[Id] = [m].[RootId]
      INNER JOIN [Leaf] AS [l] ON [m].[Id] = [l].[ModdleAId]
      ORDER BY [t].[Id], [m].[Id]
dbug: 27/04/2021 15:11:01.420 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 27/04/2021 15:11:01.420 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command)
      A data reader was disposed.
dbug: 27/04/2021 15:11:01.421 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closing connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
dbug: 27/04/2021 15:11:01.421 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection)
      Closed connection to database 'Temp' on server 'tcp:test.db.sales.mycompany.co.uk'.
Root 1 leaves: 1
Root 3 leaves: 0
dbug: 27/04/2021 15:11:01.426 CoreEventId.ContextDisposed[10407] (Microsoft.EntityFrameworkCore.Infrastructure)
      'Context' disposed.

C:\Projects\EfCoreOwnershipIssue\bin\Debug\net5.0\EfCoreOwnershipIssue.exe (process 19056) exited with code 0.
To automatically close the console when debugging stops, enable Tools->Options->Debugging->Automatically close the console when debugging stops.
Press any key to close this window . . .

Provider and version information

  • EF Core version: 5.0.5
  • Database provider:Microsoft.EntityFrameworkCore.SqlServer
  • Target framework: .NET 5.0
  • Operating system: Windows 10 Pro 1909
  • IDE: Visual Studio 2019 16.9.3
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Assignees

Labels

area-queryclosed-fixedThe issue has been fixed and is/will be included in the release indicated by the issue milestone.customer-reportedtype-bug

Type

No type

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions