I'm using ASP.NET Core 2.0 and EF Core 2.0.
I am trying to catch errors in the Web API to log them to my database. When I do so, it seems to mess up either the datareader (not closing) or the db context. I am dependency injecting the db context into the controller.
public class ClientsController : Controller
{
private VsNetTestContext moDbContext;
public ClientsController(VsNetTestContext dbContext)
{
moDbContext = dbContext;
if (GlobalExceptionHandler.DbContext == null)
{
GlobalExceptionHandler.DbContext = moDbContext;
}
}
GlobalExceptionHandler is a singleton class for tracking exceptions in the back end.
Here is an example get:
// GET api/clients/5/ABC
[HttpGet("{nav}/{id}")]
public IActionResult Get(string nav, string id)
{
try
{
var loAction = new SqlParameter("action", nav);
var loClientID = new SqlParameter("client_id", (object)id ?? DBNull.Value);
var loResult = moDbContext.client.FromSql("EXECUTE dbo.GetClientRecord @action, @client_id", loAction, loClientID).SingleOrDefault<client>();
return new ObjectResult(loResult);
}
catch (Exception ex)
{
HttpContext.Response.StatusCode = Microsoft.AspNetCore.Http.StatusCodes.Status500InternalServerError;
return new ObjectResult(GlobalExceptionHandler.Log(ex, "UpdateClientRecord"));
}
}
I'm catching the error and setting the response status to 500 so that I can log the error in my database in the Log method of my GlobalExceptionHandler:
public static void Log()
{
//Writes exception data to the database
try
{
if (DbContext == null)
{
return;
}
var lcolParams = new List<SqlParameter>();
lcolParams.Add(new SqlParameter("@err_title", mcErrTitle));
lcolParams.Add(new SqlParameter("@err_message", mcErrMsg));
lcolParams.Add(new SqlParameter("@err_description", mcErrDescription));
lcolParams.Add(new SqlParameter("@app_name", "VsNetTest"));
lcolParams.Add(new SqlParameter("@app_version", "1.0"));
DbContext.Database.ExecuteSqlCommand("dbo.LogApplicationError @err_title, @err_message, @err_description, @app_name, @app_version", lcolParams.ToArray());
}
catch (Exception ex)
{
//ignore
System.Diagnostics.Debug.WriteLine("Log Error: " + ex.Message);
}
}
I forced an error in the Get by adding a property to the client model that does not exist in the query result (another pain point), but it throws an exception when executing the ExecuteSqlCommand. Below is the debug output:
Application Insights Telemetry(unconfigured): { "name":"Microsoft.ApplicationInsights.Dev.Message","time":"2017-09-21T11:56:49.4156731Z","tags":{ "ai.application.ver":"1.0.0.0","ai.internal.sdkVersion":"aspnet5c:2.1.1","ai.internal.nodeName":"CTAPLAPTOP4","ai.operation.id":"a52ef379-4f366ebbd2a82b55","ai.operation.name":"GET Clients/Get [id/nav]","ai.cloud.roleInstance":"CTAPLAPTOP4","ai.operation.parentId":"|a52ef379-4f366ebbd2a82b55.","ai.location.ip":"127.0.0.1"},"data":{ "baseType":"MessageData","baseData":{ "ver":2,"message":"Executed DbCommand (59ms) [Parameters=[action='?' (Size = 1), client_id='?'], CommandType='Text', CommandTimeout='30']\r\nEXECUTE dbo.GetClientRecord @action, @client_id","severityLevel":"Information","properties":{ "DeveloperMode":"true","CategoryName":"Microsoft.EntityFrameworkCore.Database.Command","{OriginalFormat}":"Executed DbCommand ({elapsed}ms) [Parameters=[{parameters}], CommandType='{commandType}', CommandTimeout='{commandTimeout}']{newLine}{commandText}","commandType":"Text","elapsed":"59","commandText":"EXECUTE dbo.GetClientRecord @action, @client_id","commandTimeout":"30","parameters":"action='?' (Size = 1), client_id='?'","AspNetCoreEnvironment":"Development"} } } }
Microsoft.EntityFrameworkCore.Database.Command:Information: Executed DbCommand(59ms) [Parameters=[action='?' (Size = 1), client_id='?'], CommandType='Text', CommandTimeout='30']
EXECUTE dbo.GetClientRecord @action, @client_id
Application Insights Telemetry (unconfigured): { "name":"Microsoft.ApplicationInsights.Dev.Exception","time":"2017-09-21T11:56:49.4890679Z","tags":{ "ai.application.ver":"1.0.0.0","ai.internal.sdkVersion":"aspnet5c:2.1.1","ai.internal.nodeName":"CTAPLAPTOP4","ai.operation.id":"a52ef379-4f366ebbd2a82b55","ai.operation.name":"GET Clients/Get [id/nav]","ai.cloud.roleInstance":"CTAPLAPTOP4","ai.operation.parentId":"|a52ef379-4f366ebbd2a82b55.","ai.location.ip":"127.0.0.1"},"data":{ "baseType":"ExceptionData","baseData":{ "ver":2,"properties":{ "DeveloperMode":"true","CategoryName":"Microsoft.EntityFrameworkCore.Query","error":"System.InvalidOperationException: The required column 'extra_field' was not present in the results of a 'FromSql' operation.\r\n at Microsoft.EntityFrameworkCore.Query.Sql.Internal.FromSqlNonComposedQuerySqlGenerator.CreateValueBufferFactory(IRelationalValueBufferFactoryFactory relationalValueBufferFactoryFactory, DbDataReader dataReader)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.<NotifyReaderCreated>b__11_0(FactoryAndReader s)\r\n at Microsoft.EntityFrameworkCore.Internal.NonCapturingLazyInitializer.EnsureInitialized[TParam,TValue](TValue& target, TParam param, Func`2 valueFactory)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.NotifyReaderCreated(DbDataReader dataReader)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.BufferlessMoveNext(Boolean buffer)\r\n at Microsoft.EntityFrameworkCore.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.MoveNext()\r\n at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)\r\n at lambda_method(Closure , QueryContext )\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.<>c__DisplayClass17_0`1.<CompileQueryCore>b__0(QueryContext qc)","{OriginalFormat}":"An exception occurred in the database while iterating the results of a query for context type '{contextType}'.{newline}{error}","Exception":"System.InvalidOperationException: The required column 'extra_field' was not present in the results of a 'FromSql' operation.\r\n at Microsoft.EntityFrameworkCore.Query.Sql.Internal.FromSqlNonComposedQuerySqlGenerator.CreateValueBufferFactory(IRelationalValueBufferFactoryFactory relationalValueBufferFactoryFactory, DbDataReader dataReader)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.<NotifyReaderCreated>b__11_0(FactoryAndReader s)\r\n at Microsoft.EntityFrameworkCore.Internal.NonCapturingLazyInitializer.EnsureInitialized[TParam,TValue](TValue& target, TParam param, Func`2 valueFactory)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.NotifyReaderCreated(DbDataReader dataReader)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.BufferlessMoveNext(Boolean buffer)\r\n at Microsoft.EntityFrameworkCore.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.MoveNext()\r\n at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)\r\n at lambda_method(Closure , QueryContext )\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.<>c__DisplayClass17_0`1.<CompileQueryCore>b__0(QueryContext qc)","AspNetCoreEnvironment":"Development","contextType":"WebApiAureliaCli.Models.VsNetTestContext"},"exceptions":[{"id":23492147,"typeName":"System.InvalidOperationException","message":"An exception occurred in the database while iterating the results of a query for context type 'WebApiAureliaCli.Models.VsNetTestContext'.\r\nSystem.InvalidOperationException: The required column 'extra_field' was not present in the results of a 'FromSql' operation.\r\n at Microsoft.EntityFrameworkCore.Query.Sql.Internal.FromSqlNonComposedQuerySqlGenerator.CreateValueBufferFactory(IRelationalValueBufferFactoryFactory relationalValueBufferFactoryFactory, DbDataReader dataReader)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.<NotifyReaderCreated>b__11_0(FactoryAndReader s)\r\n at Microsoft.EntityFrameworkCore.Internal.NonCapturingLazyInitializer.EnsureInitialized[TParam,TValue](TValue& target, TParam param, Func`2 valueFactory)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.NotifyReaderCreated(DbDataReader dataReader)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.BufferlessMoveNext(Boolean buffer)\r\n at Microsoft.EntityFrameworkCore.Storage.Internal.SqlServerExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.MoveNext()\r\n at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)\r\n at lambda_method(Closure , QueryContext )\r\n at Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.<>c__DisplayClass17_0`1.<CompileQueryCore>b__0(QueryContext qc)","hasFullStack":true,"parsedStack":[{"level":0,"method":"Microsoft.EntityFrameworkCore.Query.Sql.Internal.FromSqlNonComposedQuerySqlGenerator.CreateValueBufferFactory","assembly":"Microsoft.EntityFrameworkCore.Relational, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"},{"level":1,"method":"Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.<NotifyReaderCreated>b__11_0","assembly":"Microsoft.EntityFrameworkCore.Relational, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"},{"level":2,"method":"Microsoft.EntityFrameworkCore.Internal.NonCapturingLazyInitializer.EnsureInitialized","assembly":"Microsoft.EntityFrameworkCore, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"},{"level":3,"method":"Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.NotifyReaderCreated","assembly":"Microsoft.EntityFrameworkCore.Relational, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"},{"level":4,"method":"Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1+Enumerator.BufferlessMoveNext","assembly":"Microsoft.EntityFrameworkCore.Relational, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"},{"level":5,"method":"Microsoft.EntityFrameworkCore.Storage.Internal.SqlServerExecutionStrategy.Execute","assembly":"Microsoft.EntityFrameworkCore.SqlServer, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"},{"level":6,"method":"Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1+Enumerator.MoveNext","assembly":"Microsoft.EntityFrameworkCore.Relational, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"},{"level":7,"method":"System.Linq.Enumerable.SingleOrDefault","assembly":"System.Linq, Version=4.2.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"},{"level":8,"method":"lambda_method","assembly":"Anonymously Hosted DynamicMethods Assembly, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null"},{"level":9,"method":"Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler+<>c__DisplayClass17_0`1.<CompileQueryCore>b__0","assembly":"Microsoft.EntityFrameworkCore, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60"}]}],"severityLevel":"Error"}}}
Microsoft.EntityFrameworkCore.Query:Error: An exception occurred in the database while iterating the results of a query for context type 'WebApiAureliaCli.Models.VsNetTestContext'.
System.InvalidOperationException: The required column 'extra_field' was not present in the results of a 'FromSql' operation.
at Microsoft.EntityFrameworkCore.Query.Sql.Internal.FromSqlNonComposedQuerySqlGenerator.CreateValueBufferFactory(IRelationalValueBufferFactoryFactory relationalValueBufferFactoryFactory, DbDataReader dataReader)
at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.<NotifyReaderCreated>b__11_0(FactoryAndReader s)
at Microsoft.EntityFrameworkCore.Internal.NonCapturingLazyInitializer.EnsureInitialized[TParam, TValue](TValue& target, TParam param, Func`2 valueFactory)
at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.NotifyReaderCreated(DbDataReader dataReader)
at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.BufferlessMoveNext(Boolean buffer)
at Microsoft.EntityFrameworkCore.Storage.Internal.SqlServerExecutionStrategy.Execute[TState, TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.MoveNext()
at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)
at lambda_method(Closure , QueryContext )
at Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.<>c__DisplayClass17_0`1.<CompileQueryCore>b__0(QueryContext qc)
System.InvalidOperationException: The required column 'extra_field' was not present in the results of a 'FromSql' operation.
at Microsoft.EntityFrameworkCore.Query.Sql.Internal.FromSqlNonComposedQuerySqlGenerator.CreateValueBufferFactory(IRelationalValueBufferFactoryFactory relationalValueBufferFactoryFactory, DbDataReader dataReader)
at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.<NotifyReaderCreated>b__11_0(FactoryAndReader s)
at Microsoft.EntityFrameworkCore.Internal.NonCapturingLazyInitializer.EnsureInitialized[TParam, TValue](TValue& target, TParam param, Func`2 valueFactory)
at Microsoft.EntityFrameworkCore.Query.Internal.ShaperCommandContext.NotifyReaderCreated(DbDataReader dataReader)
at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.BufferlessMoveNext(Boolean buffer)
at Microsoft.EntityFrameworkCore.Storage.Internal.SqlServerExecutionStrategy.Execute[TState, TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.Enumerator.MoveNext()
at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)
at lambda_method(Closure , QueryContext )
at Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.<>c__DisplayClass17_0`1.<CompileQueryCore>b__0(QueryContext qc)
Exception thrown: 'System.InvalidOperationException' in Microsoft.EntityFrameworkCore.dll
Exception thrown: 'System.ObjectDisposedException' in Microsoft.EntityFrameworkCore.dll
Log Error: Cannot access a disposed object. A common cause of this error is disposing a context that was resolved from dependency injection and then later trying to use the same context instance elsewhere in your application. This may occur if you are calling Dispose() on the context, or wrapping the context in a using statement. If you are using dependency injection, you should let the dependency injection container take care of disposing context instances.
Object name: 'VsNetTestContext'.
Application Insights Telemetry(unconfigured): { "name":"Microsoft.ApplicationInsights.Dev.Message","time":"2017-09-21T11:56:49.6463034Z","tags":{ "ai.application.ver":"1.0.0.0","ai.internal.sdkVersion":"aspnet5c:2.1.1","ai.internal.nodeName":"CTAPLAPTOP4","ai.operation.id":"a52ef379-4f366ebbd2a82b55","ai.operation.name":"GET Clients/Get [id/nav]","ai.cloud.roleInstance":"CTAPLAPTOP4","ai.operation.parentId":"|a52ef379-4f366ebbd2a82b55.","ai.location.ip":"127.0.0.1"},"data":{ "baseType":"MessageData","baseData":{ "ver":2,"message":"Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.","severityLevel":"Information","properties":{ "DeveloperMode":"true","CategoryName":"Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor","{OriginalFormat}":"Executing ObjectResult, writing value {Value}.","AspNetCoreEnvironment":"Development","Value":"Microsoft.AspNetCore.Mvc.ControllerContext"} } } }
Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor:Information: Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
Application Insights Telemetry (unconfigured): { "name":"Microsoft.ApplicationInsights.Dev.Message","time":"2017-09-21T11:56:49.6559626Z","tags":{ "ai.application.ver":"1.0.0.0","ai.internal.sdkVersion":"aspnet5c:2.1.1","ai.internal.nodeName":"CTAPLAPTOP4","ai.operation.id":"a52ef379-4f366ebbd2a82b55","ai.operation.name":"GET Clients/Get [id/nav]","ai.cloud.roleInstance":"CTAPLAPTOP4","ai.operation.parentId":"|a52ef379-4f366ebbd2a82b55.","ai.location.ip":"127.0.0.1"},"data":{ "baseType":"MessageData","baseData":{ "ver":2,"message":"Executed action WebApiAureliaCli.Controllers.ClientsController.Get (WebApiAureliaCliWebpack) in 375.9021ms","severityLevel":"Information","properties":{ "DeveloperMode":"true","CategoryName":"Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker","ElapsedMilliseconds":"375.9021","{OriginalFormat}":"Executed action {ActionName} in {ElapsedMilliseconds}ms","ActionName":"WebApiAureliaCli.Controllers.ClientsController.Get (WebApiAureliaCliWebpack)","AspNetCoreEnvironment":"Development"} } } }
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action WebApiAureliaCli.Controllers.ClientsController.Get(WebApiAureliaCliWebpack) in 375.9021ms
Application Insights Telemetry(unconfigured): { "name":"Microsoft.ApplicationInsights.Dev.Message","time":"2017-09-21T11:56:49.6666798Z","tags":{ "ai.application.ver":"1.0.0.0","ai.internal.sdkVersion":"aspnet5c:2.1.1","ai.internal.nodeName":"CTAPLAPTOP4","ai.operation.id":"a52ef379-4f366ebbd2a82b55","ai.operation.name":"GET Clients/Get [id/nav]","ai.cloud.roleInstance":"CTAPLAPTOP4","ai.operation.parentId":"|a52ef379-4f366ebbd2a82b55.","ai.location.ip":"127.0.0.1"},"data":{ "baseType":"MessageData","baseData":{ "ver":2,"message":"Request finished in 403.6099ms 500 application/json; charset=utf-8","severityLevel":"Information","properties":{ "DeveloperMode":"true","CategoryName":"Microsoft.AspNetCore.Hosting.Internal.WebHost","ElapsedMilliseconds":"403.6099","ContentType":"application/json; charset=utf-8","AspNetCoreEnvironment":"Development","StatusCode":"500"} } } }
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 403.6099ms 500 application/json; charset=utf-8
Application Insights Telemetry(unconfigured): { "name":"Microsoft.ApplicationInsights.Dev.Request","time":"2017-09-21T11:56:49.2629283Z","tags":{ "ai.internal.sdkVersion":"aspnet5c:2.1.1","ai.application.ver":"1.0.0.0","ai.internal.nodeName":"CTAPLAPTOP4","ai.operation.id":"a52ef379-4f366ebbd2a82b55","ai.operation.name":"GET Clients/Get [id/nav]","ai.cloud.roleInstance":"CTAPLAPTOP4","ai.location.ip":"127.0.0.1"},"data":{ "baseType":"RequestData","baseData":{ "ver":2,"id":"|a52ef379-4f366ebbd2a82b55.","name":"GET Clients/Get [id/nav]","duration":"00:00:00.4130153","success":false,"responseCode":"500","url":"http://localhost:5813/api/clients/1/","properties":{ "DeveloperMode":"true","httpMethod":"GET","AspNetCoreEnvironment":"Development"} } } }
Clearly I am not disposing the context in any way. Why am I getting the disposed object error on my context? This seems like a reasonable approach to catching and tracking exceptions.
EDIT: I should mention that if I remove the exception handling, the 500 response has nothing in it about the exception that occurred. So, no way to find out what went wrong on either the server or the client.