RequestId is not matching

[terryaney]

When I run this repo and generate 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:

1. Watching the Pluralsight course, the screen shots seemed to be showing RequestId properly on the error page vs the SpanId. How is that possible?
2. I implemented a new project and to my knowledge reimplemented everything the same way you did in your sample, yet I do not get SpanId, TraceId, or ParentId in my log properties. Do you happen to know what I might have done to not get these?
3. Should the 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)?

[terryaney]

Note: 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 I think.

[dahlsailrunner]

You may be on to something, but I'll review as soon as I can. Will likely be this weekend when I have a chance to look more in depth.

[terryaney]

Thanks. This comment seems to explain why the values are missing in .NET 5. Although, I did create an issue because they seem to be completely different values/formats from the .NET Core 3.1 version and I'm not sure if that is expected or not.

[terryaney]

Ugh. I don't know where it went, but I wrote up a pretty big comment/solution to this and am 95% certain I submitted it. Most likely the 5% chance is what really happened, so I'll try to remember/paraphrase.

This article explains how HttpContext is often used incorrectly. For whatever reason (I can't remember if I figured out and have forgotten now or not), new-ing up a HttpClient and passing in a new StandardHttpMessageHandler in BookList PageModel is what causes the SpanId values to not match. To fix that, and gain the benefits of the article previously mentioned, this was how I solved:

Startup:

services
	.AddHttpContextAccessor() // So that IHttpContextAccessor can be DI in StandardHttpMessageHandler
	.AddTransient<StandardHttpMessageHandler>() // So that StandardHttpMessageHandler can be used by AddHttpClient
	.AddHttpClient("API") // Following pattern of article
	.AddHttpMessageHandler<StandardHttpMessageHandler>(); // Configure that the 'API' client uses this DelegatingHandler

StandardHttpMessageHandler (just showing constructor which is only thing that changed)

	public StandardHttpMessageHandler(IHttpContextAccessor httpContextAccessor, ILogger<StandardHttpMessageHandler> logger)
	{
		_httpContext = httpContextAccessor.HttpContext;
		_logger = logger;
	}

BookList PageModel

public class BookListModel : BasePageModel
{
	private readonly IHttpClientFactory httpClientFactory;
	public List<BookModel> Books;

	public BookListModel(IHttpClientFactory httpClientFactory, ILogger<BookListModel> logger, IScopeInformation scope) : base(logger, scope)
	{
		this.httpClientFactory = httpClientFactory;
	}

	public async Task OnGetAsync()
	{
		var response = await httpClientFactory.CreateClient("API").GetAsync("https://localhost:44322/api/Book");
		Books = JsonConvert.DeserializeObject<List<BookModel>>(
			await response.Content.ReadAsStringAsync()).OrderByDescending(a => a.Id).ToList();
	}
}

No 'API Error ID' Implementation
Correct me if I'm wrong, but the whole point for the ApiExceptionMiddleware and its communication/coordination with the site was so that you could find the logging information/error from the Web Api.

Since I was able to get SpanId matching across all logging for web and api, I didn't feel I needed that 'API Error ID'. The 'Request ID' reported on the error page would point to a log event, and then the SpanId could be used to find all correlated events. Following the same pattern, I just let API exceptions cause a throw (same as your StandardHttpMessageHandler ultimately did) by implementing the following...

Startup:

services
	.AddHttpContextAccessor() // So that IHttpContextAccessor can be DI in StandardHttpMessageHandler
	.AddTransient<EnsureSuccessStatusCodeHandler>() 
	.AddHttpClient("API")
	.AddHttpMessageHandler<EnsureSuccessStatusCodeHandler>();

EnsureSuccessStatusCodeHandler (simply calls EnsureSuccessStatusCode which throws if not success):

public class EnsureSuccessStatusCodeHandler : DelegatingHandler
{
	protected override async Task<HttpResponseMessage> SendAsync( HttpRequestMessage request, CancellationToken cancellationToken )
	{
		var response = await base.SendAsync( request, cancellationToken );

		response.EnsureSuccessStatusCode();

		return response;
	}
}

And to fix issue with .NET 5 not logging SpanId, TraceId, ParentId
In startup:

host.ConfigureLogging( loggingBuilder =>
{
	// See comment in ActivityEnricher
	loggingBuilder.Configure( options =>
	{
		options.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId;
	} );
} );

Configuring SeriLog:

var loggerConfiguration = new LoggerConfiguration()
	.ReadFrom.Configuration( configuration )
	.Enrich.FromLogContext()
	.Enrich.With<ActivityEnricher>();

ActivityEnricher

// https://github.com/serilog/serilog-aspnetcore/issues/207#issuecomment-702665756
// .Net 5/Serilog doesn't trace TraceId, SpanId, or ParentId
public class ActivityEnricher : ILogEventEnricher
{
	public void Enrich( LogEvent logEvent, ILogEventPropertyFactory propertyFactory )
	{
		var activity = Activity.Current;

		if ( activity == null ) return;

		logEvent.AddPropertyIfAbsent( new LogEventProperty( "SpanId", new ScalarValue( activity.GetSpanId() ) ) );
		logEvent.AddPropertyIfAbsent( new LogEventProperty( "TraceId", new ScalarValue( activity.GetTraceId() ) ) );
		logEvent.AddPropertyIfAbsent( new LogEventProperty( "ParentId", new ScalarValue( activity.GetParentId() ) ) );
	}
}

internal static class ActivityExtensions
{
	public static string GetSpanId( this Activity activity )
	{
		return activity.IdFormat switch
		{
			ActivityIdFormat.Hierarchical => activity.Id,
			ActivityIdFormat.W3C => activity.SpanId.ToHexString(),
			_ => null,
		} ?? string.Empty;
	}

	public static string GetTraceId( this Activity activity )
	{
		return activity.IdFormat switch
		{
			ActivityIdFormat.Hierarchical => activity.RootId,
			ActivityIdFormat.W3C => activity.TraceId.ToHexString(),
			_ => null,
		} ?? string.Empty;
	}

	public static string GetParentId( this Activity activity )
	{
		return activity.IdFormat switch
		{
			ActivityIdFormat.Hierarchical => activity.ParentId,
			ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(),
			_ => null,
		} ?? string.Empty;
	}
}

I'm pretty sure this is all that is needed to

[dahlsailrunner]

This looks like an awesome solution and I remember the HttpClient tickling the back of my neck a bit. If think the changes you are making would be compatible even with .net core 3.1 -- would you mind submitting them in a PR? I'd be happy to review / merge the changes -- it sounds like they are just what is needed and a better solution than what I was originally doing.