Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

A property on a nested owned entity is not being saved in the CosmosDB document #31664

Closed
martinw6 opened this issue Sep 8, 2023 · 2 comments · Fixed by #31933
Closed

A property on a nested owned entity is not being saved in the CosmosDB document #31664

martinw6 opened this issue Sep 8, 2023 · 2 comments · Fixed by #31933
Labels
area-cosmos area-model-building breaking-change closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. customer-reported type-bug
Milestone

Comments

@martinw6
Copy link

martinw6 commented Sep 8, 2023

While developing our application I have noticed what appears to be some strange behaviour with the Entity Framework CosmosDB provider (we are using the Microsoft.EntityFrameworkCore.Cosmos NuGet package version 6.0.8).

We have a 'User' entity that has a nested owned entity (a referrer), the referrer references the ID of another user entity.

When the user entity is saved, the property on the nested owned entity is not saved at all when the property on the C# record is called 'UserId'. If it is called anything else then it is saved successfully.

I'm not sure if this behaviour is expected or if it is a bug, so I thought it could be worth reporting.

I have managed to replicate the issue in a simplified form in a console app using the code below:

using Microsoft.EntityFrameworkCore; //using Microsoft.EntityFrameworkCore.Cosmos 6.0.8

namespace CosmosDbTestApp
{
    public class Program
    {
        public static async Task Main(string[] args)
        {
            using (var context = new MyDbContext())
            {
                await context.Database.EnsureDeletedAsync();
                await context.Database.EnsureCreatedAsync();

                var user1 = new User
                {
                    Id = "1",
                    Name = "Bob"
                };

                context.Add(user1);
                
                await context.SaveChangesAsync();
                
                var user2 = new User
                {
                    Id = "2",
                    Name = "Fred",
                    Referrer = new Referrer
                    {
                        UserId = "1",
                        ReasonForReferral = "IntroductionByFriend"
                    }
                };

                context.Add(user2);

                await context.SaveChangesAsync();
            }
        }
    }

    public class MyDbContext : DbContext
    {
        public DbSet<User> Users { get; set; }

        protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
            => optionsBuilder.UseCosmos(
                "https://REDACTED.documents.azure.com:443/",
                "REDACTED",
                "TestDb");

        protected override void OnModelCreating(ModelBuilder modelBuilder)
        {
            modelBuilder.Entity<User>()
                .ToContainer(nameof(User))
                .HasNoDiscriminator()
                .HasPartitionKey(d => d.Id)
                .HasKey(d => d.Id);
            
            modelBuilder.Entity<User>()
                .Property(d => d.Id);

            modelBuilder.Entity<User>().OwnsOne(
                o => o.Referrer,
                r =>
                {
                    r.Property(p => p.UserId);
                    r.Property(p => p.ReasonForReferral);
                });
        }
    }

    public record User
    {
        public string Id { get; set; }
        public string Name { get; set; } = default!;
        public Referrer? Referrer { get; set; }
    }

    public record Referrer
    {
        // If this property is named anything other than 'UserId' everything works as expected.
        // if it is called 'UserId' then this property is not saved in the Cosmos document JSON.
        public string UserId { get; set; }
        public string ReasonForReferral { get; set; } = default!;
    }
}

Running this code saves two entities like this, as you can see the second user is missing the '"UserId": "1"' property:

1

If the 'UserId' on the 'Referrer' C# record is renamed to something else, then it saves as expected:

2

My guess was that this could be something to do with the way the implicit shadow primary key is working as mentioned here:

https://learn.microsoft.com/en-us/ef/core/modeling/owned-entities#implicit-keys

So I tried adding a key to the nested entity. This saves a 'UserId' property on the referrer, but it saves it with the UserId of the current entity (a 2 instead of a 1):

using Microsoft.EntityFrameworkCore; //using Microsoft.EntityFrameworkCore.Cosmos 6.0.8

namespace CosmosDbTestApp
{
    public class Program
    {
        public static async Task Main(string[] args)
        {
            using (var context = new MyDbContext())
            {
                await context.Database.EnsureDeletedAsync();
                await context.Database.EnsureCreatedAsync();

                var user1 = new User
                {
                    Id = "1",
                    Name = "Bob"
                };

                context.Add(user1);
                
                await context.SaveChangesAsync();
                
                var user2 = new User
                {
                    Id = "2",
                    Name = "Fred",
                    Referrer = new Referrer
                    {
                        Id = "R1",
                        UserId = "1",
                        ReasonForReferral = "IntroductionByFriend"
                    }
                };

                context.Add(user2);

                await context.SaveChangesAsync();
            }
        }
    }

    public class MyDbContext : DbContext
    {
        public DbSet<User> Users { get; set; }

        protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
            => optionsBuilder.UseCosmos(
                "https://REDACTED.documents.azure.com:443/",
                "REDACTED",
                "TestDb");

        protected override void OnModelCreating(ModelBuilder modelBuilder)
        {
            modelBuilder.Entity<User>()
                .ToContainer(nameof(User))
                .HasNoDiscriminator()
                .HasPartitionKey(d => d.Id)
                .HasKey(d => d.Id);
            
            modelBuilder.Entity<User>()
                .Property(d => d.Id);

            modelBuilder.Entity<User>().OwnsOne(
                o => o.Referrer,
                r =>
                {
                    r.HasKey(p => p.Id);
                    r.Property(p => p.UserId);
                    r.Property(p => p.ReasonForReferral);
                });
        }
    }

    public record User
    {
        public string Id { get; set; }
        public string Name { get; set; } = default!;
        public Referrer? Referrer { get; set; }
    }

    public record Referrer
    {
        public string Id { get; set; } // Adding an explicit key to the nested entity make it save, but with the wrong ID, it uses the ID (2 instead of 1)
        
        // If this property is named anything other than 'UserId' everything works as expected.
        // if it is called 'UserId' then this property is not saved in the Cosmos document JSON.
        public string UserId { get; set; }
        public string ReasonForReferral { get; set; } = default!;
    }
}
3

I also tried adding 'ToJsonProperty("UserId")' on the referrer user ID mapping like this:

modelBuilder.Entity<User>().OwnsOne(
        o => o.Referrer,
       r =>
       {
              r.Property(p => p.UserId).ToJsonProperty("UserId");
              r.Property(p => p.ReasonForReferral);
        });

However this also results in the wrong ID being saved (2 instead of 1).

I am thinking this must have something to do with the fact that the property on the nested owned entity has the same name as the entity ('User') plus the name of the 'key' property for the main entity ('Id').

The simple workaround is to use a different name for this property (which is what we have done), but it would be good to get an understanding why Entity Framework is behaving this way or if we have done something wrong in the mapping.

@martinw6
Copy link
Author

martinw6 commented Sep 9, 2023

If it is any help, here are the logs for when the property is called Referrer.UserId:

warn: 09/09/2023 15:27:29.738 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.
dbug: 09/09/2023 15:27:29.750 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'Referrer.__jObject' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:27:29.750 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'User.__id' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:27:29.750 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'User.__jObject' was created in shadow state because there are no eligible CLR members with a matching name.
info: 09/09/2023 15:27:29.788 CoreEventId.ContextInitialized[10403] (Microsoft.EntityFrameworkCore.Infrastructure) 
      Entity Framework Core 6.0.8 initialized 'MyDbContext' using provider 'Microsoft.EntityFrameworkCore.Cosmos:6.0.8' with options: ServiceEndPoint=https://REDACTED.documents.azure.com:443/ Database=TestDb SensitiveDataLoggingEnabled 
dbug: 09/09/2023 15:27:30.842 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'Referrer.__jObject' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:27:30.842 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'User.__id' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:27:30.842 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'User.__jObject' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:27:32.149 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      'MyDbContext' generated value '1' for the property '__id.User'.
dbug: 09/09/2023 15:27:32.192 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      Context 'MyDbContext' started tracking 'User' entity with key '{Id: 1}'.
dbug: 09/09/2023 15:27:32.199 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update) 
      SaveChanges starting for 'MyDbContext'.
dbug: 09/09/2023 15:27:32.203 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      DetectChanges starting for 'MyDbContext'.
dbug: 09/09/2023 15:27:32.208 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      DetectChanges completed for 'MyDbContext'.
info: 09/09/2023 15:27:32.665 CosmosEventId.ExecutedCreateItem[30104] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed CreateItem (423 ms, 6.48 RU) ActivityId='34e41a82-ae30-4dc6-af71-9bc965b59e82', Container='User', Id='1', Partition='1'
dbug: 09/09/2023 15:27:32.683 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      The 'User' entity with key '{Id: 1}' tracked by 'MyDbContext' changed state from 'Added' to 'Unchanged'.
dbug: 09/09/2023 15:27:32.691 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update) 
      SaveChanges completed for 'MyDbContext' with 1 entities written to the database.
dbug: 09/09/2023 15:27:32.691 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      'MyDbContext' generated value '2' for the property '__id.User'.
dbug: 09/09/2023 15:27:32.692 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      Context 'MyDbContext' started tracking 'User' entity with key '{Id: 2}'.
dbug: 09/09/2023 15:27:32.710 CoreEventId.ForeignKeyChangeDetected[10803] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      The foreign key property 'Referrer.UserId' was detected as changed from '1' to '2' for entity with key '{UserId: 2}'.
dbug: 09/09/2023 15:27:32.716 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      Context 'MyDbContext' started tracking 'Referrer' entity with key '{UserId: 2}'.
dbug: 09/09/2023 15:27:32.716 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update) 
      SaveChanges starting for 'MyDbContext'.
dbug: 09/09/2023 15:27:32.716 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      DetectChanges starting for 'MyDbContext'.
dbug: 09/09/2023 15:27:32.719 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      DetectChanges completed for 'MyDbContext'.
info: 09/09/2023 15:27:32.744 CosmosEventId.ExecutedCreateItem[30104] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed CreateItem (25 ms, 7.05 RU) ActivityId='0dc2aa1f-f0d9-432e-9d2d-0c5eb9315d1d', Container='User', Id='2', Partition='2'
dbug: 09/09/2023 15:27:32.745 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      The 'User' entity with key '{Id: 2}' tracked by 'MyDbContext' changed state from 'Added' to 'Unchanged'.
dbug: 09/09/2023 15:27:32.745 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      The 'Referrer' entity with key '{UserId: 2}' tracked by 'MyDbContext' changed state from 'Added' to 'Unchanged'.
dbug: 09/09/2023 15:27:32.745 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update) 
      SaveChanges completed for 'MyDbContext' with 1 entities written to the database.
dbug: 09/09/2023 15:27:32.747 CoreEventId.ContextDisposed[10407] (Microsoft.EntityFrameworkCore.Infrastructure) 
      'MyDbContext' disposed.

Process finished with exit code 0.

Here are the logs when the property is named 'Referrer.UserIdRenamed':

warn: 09/09/2023 15:28:46.665 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.
dbug: 09/09/2023 15:28:46.676 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'Referrer.UserId' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:28:46.676 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'Referrer.__jObject' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:28:46.676 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'User.__id' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:28:46.676 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'User.__jObject' was created in shadow state because there are no eligible CLR members with a matching name.
info: 09/09/2023 15:28:46.714 CoreEventId.ContextInitialized[10403] (Microsoft.EntityFrameworkCore.Infrastructure) 
      Entity Framework Core 6.0.8 initialized 'MyDbContext' using provider 'Microsoft.EntityFrameworkCore.Cosmos:6.0.8' with options: ServiceEndPoint=https://REDACTED.documents.azure.com:443/ Database=TestDb SensitiveDataLoggingEnabled 
dbug: 09/09/2023 15:28:47.600 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'Referrer.UserId' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:28:47.601 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'Referrer.__jObject' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:28:47.601 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'User.__id' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:28:47.601 CoreEventId.ShadowPropertyCreated[10600] (Microsoft.EntityFrameworkCore.Model.Validation) 
      The property 'User.__jObject' was created in shadow state because there are no eligible CLR members with a matching name.
dbug: 09/09/2023 15:28:48.865 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      'MyDbContext' generated value '1' for the property '__id.User'.
dbug: 09/09/2023 15:28:48.912 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      Context 'MyDbContext' started tracking 'User' entity with key '{Id: 1}'.
dbug: 09/09/2023 15:28:48.919 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update) 
      SaveChanges starting for 'MyDbContext'.
dbug: 09/09/2023 15:28:48.922 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      DetectChanges starting for 'MyDbContext'.
dbug: 09/09/2023 15:28:48.927 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      DetectChanges completed for 'MyDbContext'.
info: 09/09/2023 15:28:49.418 CosmosEventId.ExecutedCreateItem[30104] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed CreateItem (457 ms, 6.48 RU) ActivityId='92755d9d-384f-48bd-99de-b120fd318d91', Container='User', Id='1', Partition='1'
dbug: 09/09/2023 15:28:49.437 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      The 'User' entity with key '{Id: 1}' tracked by 'MyDbContext' changed state from 'Added' to 'Unchanged'.
dbug: 09/09/2023 15:28:49.444 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update) 
      SaveChanges completed for 'MyDbContext' with 1 entities written to the database.
dbug: 09/09/2023 15:28:49.445 CoreEventId.ValueGenerated[10808] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      'MyDbContext' generated value '2' for the property '__id.User'.
dbug: 09/09/2023 15:28:49.446 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      Context 'MyDbContext' started tracking 'User' entity with key '{Id: 2}'.
dbug: 09/09/2023 15:28:49.463 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      Context 'MyDbContext' started tracking 'Referrer' entity with key '{UserId: 2}'.
dbug: 09/09/2023 15:28:49.463 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update) 
      SaveChanges starting for 'MyDbContext'.
dbug: 09/09/2023 15:28:49.463 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      DetectChanges starting for 'MyDbContext'.
dbug: 09/09/2023 15:28:49.466 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      DetectChanges completed for 'MyDbContext'.
info: 09/09/2023 15:28:49.491 CosmosEventId.ExecutedCreateItem[30104] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed CreateItem (24 ms, 7.43 RU) ActivityId='3d74d6b3-6fea-4761-8dc5-d67e22560e7e', Container='User', Id='2', Partition='2'
dbug: 09/09/2023 15:28:49.492 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      The 'User' entity with key '{Id: 2}' tracked by 'MyDbContext' changed state from 'Added' to 'Unchanged'.
dbug: 09/09/2023 15:28:49.492 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking) 
      The 'Referrer' entity with key '{UserId: 2}' tracked by 'MyDbContext' changed state from 'Added' to 'Unchanged'.
dbug: 09/09/2023 15:28:49.492 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update) 
      SaveChanges completed for 'MyDbContext' with 1 entities written to the database.
dbug: 09/09/2023 15:28:49.493 CoreEventId.ContextDisposed[10407] (Microsoft.EntityFrameworkCore.Infrastructure) 
      'MyDbContext' disposed.

The important difference seems to be these lines:

CoreEventId.ForeignKeyChangeDetected[10803] (Microsoft.EntityFrameworkCore.ChangeTracking) The foreign key property 'Referrer.UserId' was detected as changed from '1' to '2' for entity with key '{UserId: 2}'.
CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking) Context 'MyDbContext' started tracking 'Referrer' entity with key '{UserId: 2}'.

@martinw6 martinw6 reopened this Sep 9, 2023
@ajcvickers
Copy link
Member

/cc @AndriySvyryd

@AndriySvyryd AndriySvyryd self-assigned this Sep 28, 2023
@AndriySvyryd AndriySvyryd added this to the 8.0.0 milestone Oct 2, 2023
@AndriySvyryd AndriySvyryd added the closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. label Oct 2, 2023
@AndriySvyryd AndriySvyryd removed their assignment Oct 2, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-cosmos area-model-building breaking-change closed-fixed The issue has been fixed and is/will be included in the release indicated by the issue milestone. customer-reported type-bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants