Skip to content

Commit

Permalink
Docs for logging, events, and diagnostics (#2787)
Browse files Browse the repository at this point in the history
* Fixes #2615: Add information on controlling suppressing warnings and otherwise configuring EventIds
* Fixes #2557: Support logging on DB level #2557
* Fixes #2770: Add entry in TOC for logging/interceptors
* Fixes #583: Document how to use DiagnosticSource/DiagnosticListener
* Fixes #673: Document EnableSensitiveDataLogging
* Fixes #1913: Interception of database operations: InterceptionResult or InterceptionResult<DbDataReader>?
* Fixes #1543: Document database interceptors with examples
* Fixes #955: Document EnableRichDataErrorHandling
* Fixes #661: EF Core 2.1: document state change events
  • Loading branch information
ajcvickers committed Nov 10, 2020
1 parent 1fa4273 commit 18482b0
Show file tree
Hide file tree
Showing 37 changed files with 2,553 additions and 21 deletions.
2 changes: 1 addition & 1 deletion .markdownlint.json
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@
},
"MD025": { "front_matter_title": "" },
"MD028": false,
"MD033": { "allowed_elements": ["sup", "sub", "nobr", "span", "a"] },
"MD033": false,
"MD036": false,
"MD046": {
"style": "fenced"
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,151 @@
---
title: Using diagnostic listeners - EF Core
description: Using DiagnosticListener for global consumption of EF Core diagnostics
author: ajcvickers
ms.date: 10/16/2020
uid: core/logging-events-diagnostics/diagnostic-listeners
---

# Using Diagnostic Listeners in EF Core

> [!TIP]
> You can [download this article's sample](https://github.com/dotnet/EntityFramework.Docs/tree/master/samples/core/Miscellaneous/DiagnosticListeners) from GitHub.
Diagnostic listeners allow listening for any EF Core event that occurs in the current .NET process. The <xref:System.Diagnostics.DiagnosticListener> class is a part of a [common mechanism across .NET](https://github.com/dotnet/runtime/blob/master/src/libraries/System.Diagnostics.DiagnosticSource/src/DiagnosticSourceUsersGuide.md) for obtaining diagnostic information from running applications.

Diagnostic listeners are not suitable for getting events from a single DbContext instance. EF Core [interceptors](xref:core/logging-events-diagnostics/interceptors) provide access to the same events with per-context registration.

Diagnostic listeners are not designed for logging. Consider using [simple logging](xref:core/logging-events-diagnostics/simple-logging) or [Microsoft.Extensions.Logging](xref:core/logging-events-diagnostics/extensions-logging) for logging.

## Example: Observing diagnostic events

Resolving EF Core events is a two-step process. First, an [observer](/dotnet/standard/events/observer-design-pattern) for `DiagnosticListener` itself must be created:

<!--
public class DiagnosticObserver : IObserver<DiagnosticListener>
{
public void OnCompleted()
=> throw new NotImplementedException();
public void OnError(Exception error)
=> throw new NotImplementedException();
public void OnNext(DiagnosticListener value)
{
if (value.Name == DbLoggerCategory.Name) // "Microsoft.EntityFrameworkCore"
{
value.Subscribe(new KeyValueObserver());
}
}
}
-->
[!code-csharp[DiagnosticObserver](../../../samples/core/Miscellaneous/DiagnosticListeners/Program.cs?name=DiagnosticObserver)]

The `OnNext` method looks for the DiagnosticListener that comes from EF Core. This listener has the name "Microsoft.EntityFrameworkCore", which can be obtained from the <xref:Microsoft.EntityFrameworkCore.DbLoggerCategory> class as shown.

This observer must then be registered globally, for example in the application's `Main` method:

<!--
DiagnosticListener.AllListeners.Subscribe(new DiagnosticObserver());
-->
[!code-csharp[RegisterDiagnosticListener](../../../samples/core/Miscellaneous/DiagnosticListeners/Program.cs?name=RegisterDiagnosticListener)]

Second, once the EF Core DiagnosticListener is found, a new key-value observer is created to subscribe to the actual EF Core events. For example:

<!--
public class KeyValueObserver : IObserver<KeyValuePair<string, object>>
{
public void OnCompleted()
=> throw new NotImplementedException();
public void OnError(Exception error)
=> throw new NotImplementedException();
public void OnNext(KeyValuePair<string, object> value)
{
if (value.Key == CoreEventId.ContextInitialized.Name)
{
var payload = (ContextInitializedEventData)value.Value;
Console.WriteLine($"EF is initializing {payload.Context.GetType().Name} ");
}
if (value.Key == RelationalEventId.ConnectionOpening.Name)
{
var payload = (ConnectionEventData)value.Value;
Console.WriteLine($"EF is opening a connection to {payload.Connection.ConnectionString} ");
}
}
}
-->
[!code-csharp[KeyValueObserver](../../../samples/core/Miscellaneous/DiagnosticListeners/Program.cs?name=KeyValueObserver)]

The `OnNext` method is this time called with a key/value pair for each EF Core event. The key is the name of the event, which can be obtained from one of:

* <xref:Microsoft.EntityFrameworkCore.Diagnostics.CoreEventId> for events common to all EF Core database providers
* <xref:Microsoft.EntityFrameworkCore.Diagnostics.RelationalEventId> for events common to all relational database providers
* A similar class for events specific to the current database provider. For example, <xref:Microsoft.EntityFrameworkCore.Diagnostics.SqlServerEventId> for the SQL Server provider.

The value of the key/value pair is a payload type specific to the event. The type of payload to expect is documented on each event defined in these event classes.

For example, the code above handles the <xref:Microsoft.EntityFrameworkCore.Diagnostics.CoreEventId.ContextInitialized> and the <xref:Microsoft.EntityFrameworkCore.Diagnostics.RelationalEventId.ConnectionOpening> events. For the first of these, the payload is <xref:Microsoft.EntityFrameworkCore.Diagnostics.ContextInitializedEventData>. For the second, it is <xref:Microsoft.EntityFrameworkCore.Diagnostics.ConnectionEventData>.

> [!TIP]
> ToString is overridden in every EF Core event data class to generate the equivalent log message for the event. For example, calling `ContextInitializedEventData.ToString` generates "Entity Framework Core 5.0.0-rc.2.20475.6 initialized 'BlogsContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite' with options: None".
The [sample](https://github.com/dotnet/EntityFramework.Docs/tree/master/samples/core/Miscellaneous/DiagnosticListeners) contains a simple console application that makes changes to the blogging database and prints out the diagnostic events encountered.

<!--
public static void Main()
{
#region RegisterDiagnosticListener
DiagnosticListener.AllListeners.Subscribe(new DiagnosticObserver());
#endregion
using (var context = new BlogsContext())
{
context.Database.EnsureDeleted();
context.Database.EnsureCreated();
context.Add(
new Blog
{
Name = "EF Blog",
Posts =
{
new Post { Title = "EF Core 3.1!" },
new Post { Title = "EF Core 5.0!" }
}
});
context.SaveChanges();
}
using (var context = new BlogsContext())
{
var blog = context.Blogs.Include(e => e.Posts).Single();
blog.Name = "EF Core Blog";
context.Remove(blog.Posts.First());
blog.Posts.Add(new Post { Title = "EF Core 6.0!" });
context.SaveChanges();
}
#endregion
}
-->
[!code-csharp[Program](../../../samples/core/Miscellaneous/DiagnosticListeners/Program.cs?name=Program)]

The output from this code shows the events detected:

```output
EF is initializing BlogsContext
EF is opening a connection to Data Source=blogs.db;Mode=ReadOnly
EF is opening a connection to DataSource=blogs.db
EF is opening a connection to Data Source=blogs.db;Mode=ReadOnly
EF is opening a connection to DataSource=blogs.db
EF is opening a connection to DataSource=blogs.db
EF is opening a connection to DataSource=blogs.db
EF is initializing BlogsContext
EF is opening a connection to DataSource=blogs.db
EF is opening a connection to DataSource=blogs.db
```
Empty file.
133 changes: 133 additions & 0 deletions entity-framework/core/logging-events-diagnostics/events.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,133 @@
---
title: .NET events - EF Core
description: .NET events defined by EF Core
author: ajcvickers
ms.date: 10/15/2020
uid: core/logging-events-diagnostics/events
---

# .NET Events in EF Core

> [!TIP]
> You can [download the events sample](https://github.com/dotnet/EntityFramework.Docs/tree/master/samples/core/Miscellaneous/Events) from GitHub.
Entity Framework Core (EF Core) exposes [.NET events](/dotnet/standard/events/) to act as callbacks when certain things happen in the EF Core code. Events are simpler than [interceptors](xref:core/logging-events-diagnostics/interceptors) and allow more flexible registration. However, they are sync only and so cannot perform non-blocking async I/O.

Events are registered per `DbContext` instance. Use a [diagnostic listener](xref:core/logging-events-diagnostics/diagnostic-listeners) to get the same information but for all DbContext instances in the process.

## Events raised by EF Core

The following events are raised by EF Core:

| Event | Version introduced | When raised
|:------|--------------------|-------
| `DbContext.SavingChanges` <!-- Issue #2748 -->| 5.0 | At the start of <xref:Microsoft.EntityFrameworkCore.DbContext.SaveChanges%2A> or <xref:Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync%2A>
| `DbContext.SavedChanges` <!-- Issue #2748 -->| 5.0 | At the end of a successful <xref:Microsoft.EntityFrameworkCore.DbContext.SaveChanges%2A> or <xref:Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync%2A>
| `DbContext.SaveChangesFailed` <!-- Issue #2748 -->| 5.0 | At the end of a failed <xref:Microsoft.EntityFrameworkCore.DbContext.SaveChanges%2A> or <xref:Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync%2A>
| <xref:Microsoft.EntityFrameworkCore.ChangeTracking.ChangeTracker.Tracked?displayProperty=nameWithType> | 2.1 | When an entity is tracked by the context
| <xref:Microsoft.EntityFrameworkCore.ChangeTracking.ChangeTracker.StateChanged?displayProperty=nameWithType> | 2.1 | When a tracked entity changes its state

### Example: Timestamp state changes

Each entity tracked by a DbContext has an <xref:Microsoft.EntityFrameworkCore.EntityState>. For example, the `Added` state indicates that the entity will be inserted into the database.

This example uses the <xref:Microsoft.EntityFrameworkCore.ChangeTracking.ChangeTracker.Tracked> and <xref:Microsoft.EntityFrameworkCore.ChangeTracking.ChangeTracker.StateChanged> events to detect when an entity changes state. It then stamps the entity with the current time indicating when this change happened. This results in timestamps indicating when the entity was inserted, deleted, and/or last updated.

The entity types in this example implement an interface that defines the timestamp properties:

<!--
public interface IHasTimestamps
{
DateTime? Added { get; set; }
DateTime? Deleted { get; set; }
DateTime? Modified { get; set; }
}
-->
[!code-csharp[IHasTimestamps](../../../samples/core/Miscellaneous/Events/Program.cs?name=IHasTimestamps)]

A method on the application's DbContext can then set timestamps for any entity that implements this interface:

<!--
private static void UpdateTimestamps(object sender, EntityEntryEventArgs e)
{
if (e.Entry.Entity is IHasTimestamps entityWithTimestamps)
{
switch (e.Entry.State)
{
case EntityState.Deleted:
entityWithTimestamps.Deleted = DateTime.UtcNow;
Console.WriteLine($"Stamped for delete: {e.Entry.Entity}");
break;
case EntityState.Modified:
entityWithTimestamps.Modified = DateTime.UtcNow;
Console.WriteLine($"Stamped for update: {e.Entry.Entity}");
break;
case EntityState.Added:
entityWithTimestamps.Added = DateTime.UtcNow;
Console.WriteLine($"Stamped for insert: {e.Entry.Entity}");
break;
}
}
}
-->
[!code-csharp[UpdateTimestamps](../../../samples/core/Miscellaneous/Events/Program.cs?name=UpdateTimestamps)]

This method has the appropriate signature to use as an event handler for both the `Tracked` and `StateChanged` events. The handler is registered for both events in the DbContext constructor. Note that events can be attached to a DbContext at any time; it is not required that this happen in the context constructor.

<!--
public BlogsContext()
{
ChangeTracker.StateChanged += UpdateTimestamps;
ChangeTracker.Tracked += UpdateTimestamps;
}
-->
[!code-csharp[ContextConstructor](../../../samples/core/Miscellaneous/Events/Program.cs?name=ContextConstructor)]

Both events are needed because new entities fire `Tracked` events when they are first tracked. `StateChanged` events are only fired for entities that change state while they are _already_ being tracked.

The [sample](https://github.com/dotnet/EntityFramework.Docs/tree/master/samples/core/Miscellaneous/Events) for this example contains a simple console application that makes changes to the blogging database:

<!--
using (var context = new BlogsContext())
{
context.Database.EnsureDeleted();
context.Database.EnsureCreated();
context.Add(
new Blog
{
Id = 1,
Name = "EF Blog",
Posts =
{
new Post { Id = 1, Title = "EF Core 3.1!" },
new Post { Id = 2, Title = "EF Core 5.0!" }
}
});
context.SaveChanges();
}
using (var context = new BlogsContext())
{
var blog = context.Blogs.Include(e => e.Posts).Single();
blog.Name = "EF Core Blog";
context.Remove(blog.Posts.First());
blog.Posts.Add(new Post { Id = 3, Title = "EF Core 6.0!" });
context.SaveChanges();
}
-->
[!code-csharp[Demonstration](../../../samples/core/Miscellaneous/Events/Program.cs?name=Demonstration)]

The output from this code shows the state changes happening and the timestamps being applied:

```output
Stamped for insert: Blog 1 Added on: 10/15/2020 11:01:26 PM
Stamped for insert: Post 1 Added on: 10/15/2020 11:01:26 PM
Stamped for insert: Post 2 Added on: 10/15/2020 11:01:26 PM
Stamped for delete: Post 1 Added on: 10/15/2020 11:01:26 PM Deleted on: 10/15/2020 11:01:26 PM
Stamped for update: Blog 1 Added on: 10/15/2020 11:01:26 PM Modified on: 10/15/2020 11:01:26 PM
Stamped for insert: Post 3 Added on: 10/15/2020 11:01:26 PM
```
Empty file.
Loading

0 comments on commit 18482b0

Please sign in to comment.