DEV Community

Cover image for EF Core debugging part 1
Karen Payne
Karen Payne

Posted on • Updated on

EF Core debugging part 1

In this article learn about methods to examine data in-line with current code and logging to physical files with and without EF Core Interceptors.

The average developer stepping into EF Core has a learning curve which once mastered EF Core becomes extremely easy to use, well for the basics. These developers tend to not understand what is available to assist with when things do not go as planned.

Also, many of these developers come from working with a data provider, writing SQL statements in code. Some will use parameterized SQL statements while others do not so we will talk about how to protect data properly.

Source code

Requires Microsoft Visual Studio 2022, 17.4.x. Clone the following GitHub repository.

Examining changed data DebugView.LongView

Yes we can set breakpoints and inspect data in a Visual Studio local window but there is an easier way for development mode.

Create an instance of a DbContext, we will name it Context. Make some changes, before calling SaveChanges add the following line.

var temp = context.ChangeTracker.DebugView.LongView
Enter fullscreen mode Exit fullscreen mode

Set a breakpoint on the next line, when hit inspect information in the variable temp, or simply output the information to Visual Studio's Output Window.

Console.WriteLine(context.ChangeTracker.DebugView.LongView);
Enter fullscreen mode Exit fullscreen mode

Or

Debug.WriteLine(context.ChangeTracker.DebugView.LongView);
Enter fullscreen mode Exit fullscreen mode

Examining changed data Original and current values

Another method is to access original and proposed values. Here we have mocked data, make a change to a property and then examine both original and changed values.

    private static async Task EditExistingBookPeek()
    {

        int identifier = 1;

        await using var context = new BookContext();

        Book book = await context.Books.AsTracking().FirstOrDefaultAsync(b => b.Id == identifier);

        if (book is null)
        {
            return;
        }

        book!.Price += 1;

        var original = context
            .Entry(book)
            .Property(product => product.Price)
            .OriginalValue;


        var current = context
            .Entry(book)
            .Property(product => product.Price)
            .CurrentValue;

    }
Enter fullscreen mode Exit fullscreen mode

Examining changed data with an Interceptor

What is an interceptor?

From Microsoft
Entity Framework Core (EF Core) interceptors enable interception, modification, and/or suppression of EF Core operations. This includes low-level database operations such as executing a command, as well as higher-level operations, such as calls to SaveChanges.

Interceptors are different from logging and diagnostics in that they allow modification or suppression of the operation being intercepted.

Let's look at one for writing current and proposed changes to a file.

  • Override both SavingChanges and SavingChangesAsync
  • Inject a method, in this case Inspect which iterates those entities that are currently being tracked and write them to a SeriLog file as json.
  • Perform the save operation.

Model used for the interceptor

public class CompareModel
{
    public object OriginalValue { get; set; }

    public object NewValue { get; set; }
    public string EntityState { get; set; }
}
Enter fullscreen mode Exit fullscreen mode

public class AuditInterceptor : SaveChangesInterceptor
{
    public override ValueTask<InterceptionResult<int>> SavingChangesAsync(DbContextEventData eventData, InterceptionResult<int> result, CancellationToken cancellationToken = new CancellationToken())
    {
        Inspect(eventData);
        return base.SavingChangesAsync(eventData, result, cancellationToken);
    }

    public override InterceptionResult<int> SavingChanges(DbContextEventData eventData, InterceptionResult<int> result)
    {
        Inspect(eventData);
        return base.SavingChanges(eventData, result);
    }

    public override int SavedChanges(SaveChangesCompletedEventData eventData, int result)
    {
        Inspect(eventData);
        return base.SavedChanges(eventData, result);
    }

    private static void Inspect(DbContextEventData eventData)
    {
        var changesList = new List<CompareModel>();

        foreach (EntityEntry entry in eventData.Context!.ChangeTracker.Entries())
        {
            switch (entry.State)
            {
                case EntityState.Added:
                    changesList.Add(new()
                    {
                        OriginalValue = null,
                        NewValue = entry.CurrentValues.ToObject(),
                        EntityState = EntityState.Added.ToString()
                    });
                    break;
                case EntityState.Deleted:
                    changesList.Add(new()
                    {
                        OriginalValue = entry.OriginalValues.ToObject(),
                        NewValue = null,
                        EntityState = EntityState.Deleted.ToString()
                    });
                    break;
                case EntityState.Modified:
                    changesList.Add(new()
                    {
                        OriginalValue = entry.OriginalValues.ToObject(),
                        NewValue = entry.CurrentValues.ToObject(),
                        EntityState = EntityState.Modified.ToString()
                    });
                    break;
                case EntityState.Detached:
                    break;
                case EntityState.Unchanged:
                    break;
                default:
                    throw new ArgumentOutOfRangeException();
            }

            Log.Information($"\nchange list:{changesList.ToJson()}");
        }
    }
}
Enter fullscreen mode Exit fullscreen mode

Sample data logged to a file

Results for several changed records

[2023-01-21 13:05:54.172 [Information] 
change list:[
  {
    "OriginalValue": {
      "Id": 1,
      "Title": "C# in Depth",
      "Price": 44.99,
      "CategoryId": 1
    },
    "NewValue": {
      "Id": 1,
      "Title": "C# in Depth - changed",
      "Price": 54.99,
      "CategoryId": 1
    },
    "EntityState": "Modified"
  },
  {
    "OriginalValue": {
      "Id": 4,
      "Title": "Entity Framework Core in Action",
      "Price": 55.99,
      "CategoryId": 2
    },
    "NewValue": {
      "Id": 4,
      "Title": "Entity Framework Core in Action - updated",
      "Price": 45.99,
      "CategoryId": 2
    },
    "EntityState": "Modified"
  }
]
Enter fullscreen mode Exit fullscreen mode

Using a third party library for logging

There are a number of logging libraries, for this article we will use SeriLog which is easy to use and easy (for the most part) to configure via code or via settings in appsettings.json file.

NuGet packages

For this project, SeriLog is setup under Classes\Program.cs. I recomment commenting out the .WriteTo.Console(theme: AnsiConsoleTheme.Code) for this project as the .WriteTo.File(Path.Combine(AppDomain.CurrentDomain.BaseDirectory, "LogFiles", "EF-Log.txt") captures the same information.

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Verbose()
    .WriteTo.Console(theme: AnsiConsoleTheme.Code)
    .WriteTo.File(Path.Combine(AppDomain.CurrentDomain.BaseDirectory, "LogFiles", "EF-Log.txt"),
        rollingInterval: RollingInterval.Day,
        outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff} [{Level}] {Message}{NewLine}{Exception}")
    .CreateLogger();
Enter fullscreen mode Exit fullscreen mode

For a web app, in prgram.cs

if (builder.Environment.IsDevelopment())
{
    Log.Logger = new LoggerConfiguration()
        .MinimumLevel.Verbose()
        .WriteTo.Console(theme: AnsiConsoleTheme.Code)
        .WriteTo.File(Path.Combine(AppDomain.CurrentDomain.BaseDirectory, "LogFiles", "Log.txt"), 
            rollingInterval: RollingInterval.Day, 
            outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff} [{Level}] {Message}{NewLine}{Exception}")
        .CreateLogger();
Enter fullscreen mode Exit fullscreen mode

In BookContext a new option has been added for SeriLog

private static void SeriLogging(DbContextOptionsBuilder optionsBuilder)
{

    optionsBuilder
        .UseSqlServer(ConnectionString())
        .EnableSensitiveDataLogging()
        .LogTo(Log.Logger.Information, LogLevel.Information, null)
        .EnableDetailedErrors();

}
Enter fullscreen mode Exit fullscreen mode

Safe guarding data

When writing SQL for a data provider without parameters, data is exposed to hackers. With EF Core, pass data with a variable or parameter and the data is exposed.

Example, run this code and the values for the properties are exposed.

context.Books.Add(new Book()
{
    Price = 11.45m, 
    Title = "My second book", 
    CategoryId = 1, 
    Category = context.Categories.FirstOrDefault(x => x.CategoryId == 1)
});

Enter fullscreen mode Exit fullscreen mode

In this case variables are sent, nothing is exposed

decimal value = 11.45m;
string bookTitle = "My second book";
int categoryIdentifier = 1;

context.Books.Add(new Book()
{
    Price = value, 
    Title = bookTitle, 
    CategoryId = categoryIdentifier, 
    Category = context.Categories.FirstOrDefault(x => x.CategoryId == categoryIdentifier)
});
Enter fullscreen mode Exit fullscreen mode

If we log the transaction via general logging for the DbContext as per the last sample, each value are not visible

public static void StandardLogging(DbContextOptionsBuilder optionsBuilder)
{

    optionsBuilder
        .UseSqlServer(ConnectionString())
        .LogTo(message => Debug.WriteLine(message));

}
Enter fullscreen mode Exit fullscreen mode

For debug purposes (and only in development mode) add EnableSensitiveDataLogging to enable inspecting for property values.

public static void StandardLogging(DbContextOptionsBuilder optionsBuilder)
{

    optionsBuilder
        .UseSqlServer(ConnectionString())
        .EnableSensitiveDataLogging()
        .LogTo(message => Debug.WriteLine(message));

}
Enter fullscreen mode Exit fullscreen mode

In closing

For a novice developer what has been presented can literally save hours of time attempting to figure problems with code. Take time to study the code presented rather than simply copy and paste into a project which without proper understanding can become troublesome.

There are two console projects include with commented code along with details in their respective readme files.

Top comments (5)

Collapse
 
thomasardal profile image
Thomas Ardal

Nice article. BTW, there's a markdown-problem with one of the links in Using a third party library for logging section.

Collapse
 
karenpayneoregon profile image
Karen Payne

Thanks Thomas, also noticed I did not provide the link for the GitHub repository which I added today.

Collapse
 
hervehobbes profile image
Hervé

Hello, thank you for the article, is there a second part ?

Collapse
 
karenpayneoregon profile image
Karen Payne

Yes when EF Core 8 is released.

Collapse
 
hervehobbes profile image
Hervé

Thank you.