Efcore: Relationship from 'User' to 'Customer' not configured because there are multiple properties on one entity type

[fschlaef]

Since updating to 2.1.0-preview1, I noticed these messages popping at startup.
These are apparently due to multiple foreign keys on one table referencing the same table.

For example :

Customer -> What user created the customer (references User)
Customer -> What user modified the customer (references User)

There are no errors or exceptions thrown but the message spam considerably slows down startup.
My application with 170+ keys takes a full minute to start, and it worked fine in 2.0.1.

The models and context are straight from Scaffold-DbContext with no alteration.

Steps to reproduce

Here is a repro for the issue.

```c#
using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.Logging;
using System;
using System.Collections.Generic;

namespace MultipleRelationshipsBug
{
class Program
{
static void Main(string[] args)
{
using (var context = new MyContext())
{
context.Database.EnsureCreated();
}

        Console.Read();
    }
}

public partial class MyContext : DbContext
{
    public virtual DbSet<Customer> Customer { get; set; }
    public virtual DbSet<User> User { get; set; }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        if (!optionsBuilder.IsConfigured)
        {
            optionsBuilder.UseSqlServer(@"Server=.;Database=MultipleRelationshipsBug;Trusted_Connection=True;MultipleActiveResultSets=true")
                            .EnableSensitiveDataLogging()
                            .UseLoggerFactory(new LoggerFactory().AddConsole(LogLevel.Debug));
        }
    }

    protected override void OnModelCreating(ModelBuilder modelBuilder)
    {
        modelBuilder.Entity<Customer>(entity =>
        {
            entity.Property(e => e.Id).HasColumnName("id");

            entity.Property(e => e.CreatedByFk).HasColumnName("createdBy_fk");

            entity.Property(e => e.ModifiedByFk).HasColumnName("modifiedBy_fk");

            entity.HasOne(d => d.CreatedByFkNavigation)
                .WithMany(p => p.CustomerCreatedByFkNavigation)
                .HasForeignKey(d => d.CreatedByFk)
                .OnDelete(DeleteBehavior.ClientSetNull)
                .HasConstraintName("FK_Customer_UserCreated");

            entity.HasOne(d => d.ModifiedByFkNavigation)
                .WithMany(p => p.CustomerModifiedByFkNavigation)
                .HasForeignKey(d => d.ModifiedByFk)
                .OnDelete(DeleteBehavior.ClientSetNull)
                .HasConstraintName("FK_Customer_UserModified");
        });

        modelBuilder.Entity<User>(entity =>
        {
            entity.Property(e => e.Id).HasColumnName("id");
        });
    }
}

public partial class User
{
    public User()
    {
        CustomerCreatedByFkNavigation = new HashSet<Customer>();
        CustomerModifiedByFkNavigation = new HashSet<Customer>();
    }

    public int Id { get; set; }

    public ICollection<Customer> CustomerCreatedByFkNavigation { get; set; }
    public ICollection<Customer> CustomerModifiedByFkNavigation { get; set; }
}

public partial class Customer
{
    public int Id { get; set; }
    public int CreatedByFk { get; set; }
    public int ModifiedByFk { get; set; }

    public User CreatedByFkNavigation { get; set; }
    public User ModifiedByFkNavigation { get; set; }
}

}

My .csproj

Exe
netcoreapp2.1

```

Further technical details

EF Core version: 2.1.0-preview1-final
Database Provider: Microsoft.EntityFrameworkCore.SqlServer
Operating system: Windows 7 x64
IDE: Visual Studio 2017 15.6.0

[ajcvickers]

@fschlaef Thanks for reporting this. A couple of questions:

• How many lines are logged to build the model?
• What is the performance like when LogLevel is changed to Information? How about Warning?

[fschlaef]

@ajcvickers I investigated this further :

• The application takes 3 minutes to start, but VS says the debugging session lasted ~10 seconds, and increments seconds at a fraction of realtime speed. So VS is slowing down a lot.
• EDIT : I tried running without VS (just a dotnet run in a cmd.exe), same result. VS not the culprit.
• The Garbage Collector is apparently going haywire for some reason (see screenshot) and the CPU is at 100%
• The log created just for startup contains 47 000 lines regarding EF for a total of 17MB
• The messages are logged with Information level, so setting LogLevel at Information doesn't change anything, but setting at Warning removes the issue

Hope you can make something out of this !

[ajcvickers]

@fschlaef Thanks for the additional information. We're doing a couple of things in this area:

• Moving more messages to debug (won't help when running on Debug, but will help for Info level)
• Reducing the number of model building messages

The second of these changes is already in out nightly builds (see https://github.com/aspnet/EntityFrameworkCore). Could you test it and see whether the 47000 lines is reduced? Also, could you post a representative sub-section of maybe a 100 or so of the log messages?

[mnmr]

I am also experiencing this issue with 2.1.0-preview2-30365. With information level logging we get about 60 messages emitted on startup (for a DB with almost the same amount of entities). Context initialization takes less than a second, so no performance issue.

However, we are worried about the warnings, as they seem to imply that EF is ignoring part of our mapping definitions, and it's unclear what this affects or if there is anything we can do to solve it.

[fschlaef]

@ajcvickers I got some testing done with 2.1.0-preview2-30366, there are definitely improvements :

• Number of messages down from 47 000+ to 12 015 for the same database
• VS is still slowing down, but a lot less and the startup takes 45s down from 3 minutes
• A lot less madness regarding GC and CPU, see screenshot
• Messages are still logged with Information level, but with further changes we could simply add an override for LogLevel "Microsoft.EntityFrameworkCore.Model": "Information" and that would do it
• I tried scaffolding to be sure, but nothing changed in the database
• I attached a log, this is the only message logged, the same message is logged for each table in the DB, 3 times over (down to 12 previously).
• I got another message logged 12 times that I have no idea what table or field it is. Maybe completely unrelated :

[Information] The best match for foreign key properties "{'Id' : int}" are incompatible with the principal key "{'Name' : string}".

New perf graph :

Log excerpt :
ef210messages.txt

[ajcvickers]

Notes from triage:

• Wording should be changed to make it clearer that these are part of the internal conventions process and do not indicate that anything has been done wrong.
• We should consider ways to reduce the number of messages. For example, caching and de-duping.
• We should consider whether moving some of these to Trace level would help
• We should consider whether these messages will really be helpful, either for app developers or us in submitted logs.

Assigning to @AndriySvyryd to ponder and plan.

[AndriySvyryd]

These log messages can be disabled by filtering out the Model category https://docs.microsoft.com/en-us/ef/core/miscellaneous/logging or by ignoring specific messages:
.ConfigureWarnings(c => c.Ignore(CoreEventId.MultipleNavigationProperties))