Collecting database events from a .NET 6 application causes it to crash

[davidmikh]

Description

Applications that generate database operation related events (either by using EF Core or with using normal SQL queries) will crash when database operation related events are being collected from them due to a System.Reflection.AmbiguousMatchException. Below are instructions on how to repro the issue:

1. Run a .NET 6 application that does database operations either through EF Core or regular SQL commands (I can provide an example if needed via email)

2. Profile the application using dotnet-trace with the following command (this command is specific to Windows, if running on Linux the quotation marks in the providers string need to be slightly different):

dotnet-trace collect -p <PID> --providers Microsoft-Diagnostics-DiagnosticSource:00000003:5:FilterAndPayloadSpecs=\"SqlClientDiagnosticListener/System.Data.SqlClient.WriteCommandBefore@Activity1Start:-Command;Command.CommandText;ConnectionId;Operation;Command.Connection.ServerVersion;Command.CommandTimeout;Command.CommandType;Command.Connection.ConnectionString;Command.Connection.Database;Command.Connection.DataSource;Command.Connection.PacketSize\r\nSqlClientDiagnosticListener/System.Data.SqlClient.WriteCommandAfter@Activity1Stop:\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Command.CommandExecuting@Activity2Start:-Command.CommandText;Command;ConnectionId;IsAsync;Command.Connection.ClientConnectionId;Command.Connection.ServerVersion;Command.CommandTimeout;Command.CommandType;Command.Connection.ConnectionString;Command.Connection.Database;Command.Connection.DataSource;Command.Connection.PacketSize\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted@Activity2Stop:\",System.Threading.Tasks.TplEventSource

The application will then crash with the following exception:

System.Reflection.AmbiguousMatchException: 'Ambiguous match found.'

Where the stack trace looks like this:

   at System.RuntimeType.GetPropertyImpl(String name, BindingFlags bindingAttr, Binder binder, Type returnType, Type[] types, ParameterModifier[] modifiers)
   at System.Type.GetProperty(String name, BindingFlags bindingAttr)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.PropertyFetch.FetcherForProperty(Type type, String propertyName)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.Morph(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.Morph(Object args)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_1.<.ctor>g__OnEventWritten|2(KeyValuePair`2 evnt)
   at System.Diagnostics.DiagnosticSourceEventSource.CallbackObserver`1.OnNext(T value)
   at System.Diagnostics.DiagnosticListener.Write(String name, Object value)
   at Microsoft.EntityFrameworkCore.Diagnostics.IDiagnosticsLogger.DispatchEventData(EventDefinitionBase definition, EventData eventData, Boolean diagnosticSourceEnabled, Boolean simpleLogEnabled)
   at Microsoft.EntityFrameworkCore.Diagnostics.RelationalLoggerExtensions.CommandReaderExecuting(IDiagnosticsLogger`1 diagnostics, IRelationalConnection connection, DbCommand command, DbContext context, Guid commandId, Guid connectionId, DateTimeOffset startTime)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.InitializeReader(DbContext _, Boolean result)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.MoveNext()
   at EFTestApp.Program.Main() in C:\dtl-bhrb4jy0\_work\r1\a\tempTestRoot\ApexSolutions\TestCase5\DBTool_LinuxContainer_Attach_EFCore_SQLite\Program.cs:line 43

Configuration

Operating system: 64 bit Windows
.NET version: 6.0.100-preview.7.21379.14
dotnet-trace version: 5.0.236902+5366510b270d0f0ebffc9e36e9496688b20b96c2

This seems to be specific to .NET 6, though I'm not sure which version it started to appear in. If you make the application target .NET 5 instead of .NET 6 then collecting database events from it will work as expected (won't cause the application to crash).

Regression?

This is a regression, if you change the application to target .NET 5 and everything else remains the same (same application, same OS, same version of dotnet-trace) then you will be able to collect database related events without issue. This is the version of .NET 5 I tested this with: 5.0.9

Other information

There is no known workaround currently other than downgrading the version of .NET your application uses. This issue also blocks the Visual Studio Performance Profiler's database tool from supporting .NET 6 in any scenario since it collects database events from applications.

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

Applications that generate database operation related events (either by using EF Core or with using normal SQL queries) will crash when database operation related events are being collected from them due to a System.Reflection.AmbiguousMatchException. Below are instructions on how to repro the issue:

1. Run a .NET 6 application that does database operations either through EF Core or regular SQL commands (I can provide an example if needed via email)

2. Profile the application using dotnet-trace with the following command (this command is specific to Windows, if running on Linux the quotation marks in the providers string need to be slightly different):

dotnet-trace collect -p --providers Microsoft-Diagnostics-DiagnosticSource:00000003:5:FilterAndPayloadSpecs=\SqlClientDiagnosticListener/System.Data.SqlClient.WriteCommandBefore@Activity1Start:-Command;Command.CommandText;ConnectionId;Operation;Command.Connection.ServerVersion;Command.CommandTimeout;Command.CommandType;Command.Connection.ConnectionString;Command.Connection.Database;Command.Connection.DataSource;Command.Connection.PacketSize\r\nSqlClientDiagnosticListener/System.Data.SqlClient.WriteCommandAfter@Activity1Stop:\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Command.CommandExecuting@Activity2Start:-Command.CommandText;Command;ConnectionId;IsAsync;Command.Connection.ClientConnectionId;Command.Connection.ServerVersion;Command.CommandTimeout;Command.CommandType;Command.Connection.ConnectionString;Command.Connection.Database;Command.Connection.DataSource;Command.Connection.PacketSize\r\nMicrosoft.EntityFrameworkCore/Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted@Activity2Stop:,System.Threading.Tasks.TplEventSource

The application will then crash with the following exception:

System.Reflection.AmbiguousMatchException: 'Ambiguous match found.'

Where the stack trace looks like this:

at System.RuntimeType.GetPropertyImpl(String name, BindingFlags bindingAttr, Binder binder, Type returnType, Type[] types, ParameterModifier[] modifiers)
at System.Type.GetProperty(String name, BindingFlags bindingAttr)
at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.PropertyFetch.FetcherForProperty(Type type, String propertyName)
at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.Fetch(Object obj)
at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.Morph(Object obj)
at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.Morph(Object args)
at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_1.<.ctor>g__OnEventWritten|2(KeyValuePair2 evnt) at System.Diagnostics.DiagnosticSourceEventSource.CallbackObserver1.OnNext(T value)
at System.Diagnostics.DiagnosticListener.Write(String name, Object value)
at Microsoft.EntityFrameworkCore.Diagnostics.IDiagnosticsLogger.DispatchEventData(EventDefinitionBase definition, EventData eventData, Boolean diagnosticSourceEnabled, Boolean simpleLogEnabled)
at Microsoft.EntityFrameworkCore.Diagnostics.RelationalLoggerExtensions.CommandReaderExecuting(IDiagnosticsLogger1 diagnostics, IRelationalConnection connection, DbCommand command, DbContext context, Guid commandId, Guid connectionId, DateTimeOffset startTime) at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject) at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable1.Enumerator.InitializeReader(DbContext _, Boolean result)
at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.MoveNext()
at EFTestApp.Program.Main() in C:\dtl-bhrb4jy0_work\r1\a\tempTestRoot\ApexSolutions\TestCase5\DBTool_LinuxContainer_Attach_EFCore_SQLite\Program.cs:line 43

Configuration

Operating system: 64 bit Windows
.NET version: 6.0.100-preview.7.21379.14
dotnet-trace version: 5.0.236902+5366510b270d0f0ebffc9e36e9496688b20b96c2

This seems to be specific to .NET 6, though I'm not sure which version it started to appear in. If you make the application target .NET 5 instead of .NET 6 then collecting database events from it will work as expected (won't cause the application to crash).

Regression?

This is a regression, if you change the application to target .NET 5 and everything else remains the same (same application, same OS, same version of dotnet-trace) then you will be able to collect database related events without issue. This is the version of .NET 5 I tested this with: 5.0.9

Other information

There is no known workaround currently other than downgrading the version of .NET your application uses. This issue also blocks the Visual Studio Performance Profiler's database tool from supporting .NET 6 in any scenario since it collects database events from applications.

Author:	davidmikh
Assignees:	-
Labels:	area-System.Diagnostics.Tracing, untriaged
Milestone:	-

[tommcdon]

@josalem This is a regression between .NET 5 and .NET 6, possibly related to changes in DiagnosticSourceEventSource.

[davmason]

I took a look, it's failing due to the code added in #55613. The EF code is trying to fire an event with a SqliteCommand as an argument and it has a Connection property, but so does its base class DbCommand. The call to GetProperty throws an AmbiguousMatchException.

Changing from typeInfo.GetProperty() to typeInfo.GetProperties().FirstOrDefault() would fix the exception, but I don't know off the top of my head if that does what we want. Presumably we want to prefer the derived class fields over the base class fields.

It's definitely possible to fix once we give it some thought.

[tarekgh]

Would it make sense calling first typeInfo.GetDeclaredProperty and if it returns null, at that time call typeInfo.GetProperties().FirstOrDefault()? I am not sure if this will affect the performance, but I am not expecting that regress old scenarios but maybe be slower for new scenarios which need getting the property from parent classes.

[davmason]

Would it make sense calling first typeInfo.GetDeclaredProperty and if it returns null, at that time call typeInfo.GetProperties().FirstOrDefault()? I am not sure if this will affect the performance, but I am not expecting that regress old scenarios but maybe be slower for new scenarios which need getting the property from parent classes.

I had starting thinking along the same lines. The performance of this code that generates event manifests is already pretty bad, I doubt one extra call would make things noticeably worse. This is probably a good solution to start with