I was running code from this repo and generating an error from the Book.API, I get an error page like this:
The request ID is |574e8e13-4e9d31fed64d4793.
When I look at the log entry in the file, I see:
{
"Timestamp": "2021-01-25T18:07:24.6565993-06:00",
"Level": "Fatal",
"MessageTemplate": "BADNESS!!! Cannot open database \"Demo_EffectiveLogging\" requested by the login. The login failed.\r\nLogin failed for user 'TCA-PRECISION\\terry.aney'. -- {ErrorId}.",
"Exception": "System.Data.SqlClient.SqlException (0x80131904): Cannot open database \"Demo_EffectiveLogging\" requested by the login. The login failed.\r\nLogin failed for user 'TCA-PRECISION\\terry.aney'.\r\n at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, SqlCredential credential, Object providerInfo, String newPassword, SecureString newSecurePassword, Boolean redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSessionData, Boolean applyTransientFaultHandling, String accessToken)\r\n at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnectionOptions userOptions)\r\n at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection owningObject, DbConnectionOptions options, DbConnectionPoolKey poolKey, DbConnectionOptions userOptions)\r\n at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)\r\n at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)\r\n at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)\r\n at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)\r\n at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)\r\n at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)\r\n at System.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)\r\n at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)\r\n at System.Data.SqlClient.SqlConnection.Open()\r\n at Dapper.SqlMapper.QueryImpl[T](IDbConnection cnn, CommandDefinition command, Type effectiveType)+MoveNext() in /_/Dapper/SqlMapper.cs:line 1079\r\n at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)\r\n at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)\r\n at Dapper.SqlMapper.Query[T](IDbConnection cnn, String sql, Object param, IDbTransaction transaction, Boolean buffered, Nullable`1 commandTimeout, Nullable`1 commandType) in /_/Dapper/SqlMapper.cs:line 721\r\n at BookClub.Data.BookRepository.GetAllBooks() in C:\\Users\\terry.aney\\OneDrive\\.NET Core Tutorials\\EffectiveLogging\\BookClub.Data\\BookRepository.cs:line 33\r\n at BookClub.Logic.BookLogic.GetAllBooks(Boolean callBadMethod) in C:\\Users\\terry.aney\\OneDrive\\.NET Core Tutorials\\EffectiveLogging\\BookClub.Logic\\BookLogic.cs:line 26\r\n at BookClub.API.Controllers.BookController.GetBooks(Boolean throwException) in C:\\Users\\terry.aney\\OneDrive\\.NET Core Tutorials\\EffectiveLogging\\BookClub.API\\Controllers\\BookController.cs:line 45\r\n at lambda_method(Closure , Object )\r\n at Microsoft.Extensions.Internal.ObjectMethodExecutorAwaitable.Awaiter.GetResult()\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)\r\n at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)\r\n at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)\r\n at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)\r\n at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)\r\n at BookClub.Infrastructure.Middleware.ApiExceptionMiddleware.Invoke(HttpContext context) in C:\\Users\\terry.aney\\OneDrive\\.NET Core Tutorials\\EffectiveLogging\\BookClub.Infrastructure\\Middleware\\ApiExceptionMiddleware.cs:line 28\r\nClientConnectionId:2daf3389-b366-4b50-b1c2-651419fd247e\r\nError Number:4060,State:1,Class:11",
"Properties": {
"ErrorId": "0cc05d84-e36f-4e2b-b8e0-57bf5e465046",
"SourceContext": "BookClub.Infrastructure.Middleware.ApiExceptionMiddleware",
"RequestId": "8000017c-000c-fc00-b63f-84710c7967bb",
"RequestPath": "/api/Book",
"SpanId": "|303de91c-4b6f6e187de2f4f3.",
"TraceId": "303de91c-4b6f6e187de2f4f3",
"ParentId": ""
}
}
{
"Timestamp": "2021-01-25T18:07:24.8378974-06:00",
"Level": "Error",
"MessageTemplate": "An unhandled exception has occurred while executing the request.",
"Exception": "System.Exception: API Failure\r\n at BookClub.UI.StandardHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in C:\\Users\\terry.aney\\OneDrive\\.NET Core Tutorials\\EffectiveLogging\\BookClub.UI\\StandardHttpMessageHandler.cs:line 57\r\n at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)\r\n at BookClub.UI.Pages.BookListModel.OnGetAsync() in C:\\Users\\terry.aney\\OneDrive\\.NET Core Tutorials\\EffectiveLogging\\BookClub.UI\\Pages\\BookList.cshtml.cs:line 27\r\n at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.ExecutorFactory.NonGenericTaskHandlerMethod.Execute(Object receiver, Object[] arguments)\r\n at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.InvokeHandlerMethodAsync()\r\n at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.InvokeNextPageFilterAsync()\r\n at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.Rethrow(PageHandlerExecutedContext context)\r\n at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)\r\n at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.InvokeInnerFilterAsync()\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)\r\n at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)\r\n at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)\r\n at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)\r\n at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)",
"Properties": {
"EventId": {
"Id": 1,
"Name": "UnhandledException"
},
"SourceContext": "Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware",
"RequestId": "80000069-0004-fb00-b63f-84710c7967bb",
"RequestPath": "/BookList",
"SpanId": "|574e8e13-4e9d31fed64d4793.",
"TraceId": "574e8e13-4e9d31fed64d4793",
"ParentId": ""
}
}
So it appears to be matching the SpanId
instead of the RequestId
.
So my questions:
RequestId
properly. How is that possible that his shows correct RequestId
and mine shows SpanId
?SpanId
, TraceId
, or ParentId
in my log properties. Any guess to what I might have missed?SpanId
's match across WebApi and Website calls (i.e. the two logs above, the top one is Web API and second one is Web Site and both have unique Span/Request IDs)? Or am I supposed to use CorrelationId?TraceIdentifier
instead of looking at Activity.Current.Id?Update: I implemented my project in .NET 5. That might be the culprit for missing properties in log, but the rest of the questions remain valid.
Update: I have figured out workaround for missing properties in .NET 5. And I also have TraceId
spanning across calls from site to api, but I am wondering what SpanId
represents, I'm not finding it easily on the web.
User contributions licensed under CC BY-SA 3.0