Logging¶
MS Learn: Logging in .NET Core and ASP.NET CoreInterfaces: ILoggerFactory and ILogger<T>
Ocelot uses the standard ASP.NET Core logging interfaces ILoggerFactory and ILogger<T> at the moment.
This is encapsulated in IOcelotLogger and IOcelotLoggerFactory with the implementation for the standard ASP.NET Core logging stuff at the moment.
This is because Ocelot adds some extra info to the logs such as Request ID if it is configured.
There is a global Error Handling Middleware that catches any exceptions thrown and logs them as errors.
Finally, if logging is set to the Trace level, Ocelot will log the start, finish, and any middlewares that throw an exception, which can be quite useful.
Warning¶
If you are logging to the MS Console, you will experience terrible performance.
The community has encountered many performance issues with Ocelot, and it is always related to the Debug logging level when logging to the console/terminal.
Warning! Make sure you are logging to an appropriate destination/storage in the production environment!
Use
ErrorandCriticallevels in the production environment!Use the
Warninglevel in testing & staging environments!
These and other recommendations can be found below in the Best Practices section.
Best Practices¶
Microsoft Learn complete reference: Logging in .NET Core and ASP.NET Core
Our recommendations for achieving the best logging with Ocelot are as follows.
Ensure the minimum log level while Configure logging. The minimum log level is set in the application’s
appsettings.jsonfile. This level is defined in theLoggingsection, for example:{ "Logging": { "LogLevel": { "Default": "Information", "Microsoft.AspNetCore": "Warning" } } }
Whether you are using Serilog or the standard Microsoft providers, the logging configuration will be retrieved from this section.
builder.Configuration .SetBasePath(builder.Environment.ContentRootPath) .AddJsonFile($"appsettings.{builder.Environment.EnvironmentName}.json", false, false) // read logging settings of the environment .AddOcelot(builder.Environment);
However, there is one thing to be aware of. It is possible to use the
SetMinimumLevel()method to define the minimum logging level. Be careful and make sure you set the log level in only one place, like this:builder.Logging .ClearProviders() .SetMinimumLevel(LogLevel.Warning); // MS Console for Development and/or Testing environments only if (!builder.Environment.IsProduction()) { builder.Logging.AddConsole(); }
Please also use the
ClearProviders()method so that only the providers you wish to use are taken into account, such as the console in the example above.Ensure the proper usage of the minimum logging level for each environment: development, testing, production, etc. So, once again, read the important notes in the Warning section!
Ocelot’s logging has been improved in version 22.0: it is now possible to use a factory method for message strings that will only be executed if the minimum log level allows it.
For example, let’s take a message containing information about several variables that should only be generated if the minimum log level is
Debug. If the minimum log level isWarning, then the string is never generated.Therefore, when the string contains dynamic information (e.g.,
string.Format), or the string value is generated by a string interpolation expression, it is recommended to call theLogXmethod using an anonymous delegate via an=>expression function:Logger.LogDebug( () => $"Downstream template is {httpContext.Items.DownstreamRoute().DownstreamPathTemplate.Value}");
otherwise a constant string is sufficient
Logger.LogDebug("My const string");
Request ID¶
Also known as “Correlation ID” or HttpContext.TraceIdentifier
Ocelot allows a client to send a Request ID through an HTTP header. If provided, Ocelot uses the Request ID for logging as soon as it becomes available in the middleware pipeline. Additionally, Ocelot forwards the Request ID via the specified header to the downstream service.
You can still obtain the ASP.NET Core Request ID in the logs if you set
IncludeScopestotruein your logging configuration.The reason for not just using the bog standard framework logging is that we could not work out how to override the
RequestIdthat gets logged when settingIncludeScopestotruein the logging settings. Nicely onto the next feature.
Every log record has these 2 properties:
Property |
Description |
|---|---|
|
This represents ID of the current request as plain string, for example |
|
This represents ID of the previous request |
As an
IOcelotLoggerinterface object is injected into the constructors of service classes, the current default Ocelot logger (OcelotLoggerclass) reads these two properties from theIRequestScopedDataRepositoryinterface object.
Find out more about these properties and other details on the Request ID logging feature below.
Configuration¶
In order to use the Request ID feature, you have two options: specifying it globally or for the route.
In your ocelot.json, set the following configuration in the GlobalConfiguration section.
This setting will apply to all requests processed by Ocelot.
"GlobalConfiguration": {
"RequestIdKey": "Oc-RequestId"
}
We recommend using the
GlobalConfigurationunless it is absolutely necessary to make it route-specific.
If you want to override this for a specific route, add the following to ocelot.json:
"RequestIdKey": "Oc-RequestId"
Once Ocelot identifies incoming requests that match a route, it will set the Request ID based on the route configuration.
Problem¶
This can lead to a small issue.
If you set a GlobalConfiguration, it is possible to use one Request ID until the route is identified and then another afterward, as the Request ID key can change.
This behavior is intentional and represents the best solution we have devised for now.
In this case, the OcelotLogger will display both the current Request ID and the previous Request ID in the logs.
Below is an example of the logging when the Debug level is set for a normal request:
info: Microsoft.AspNetCore.Hosting.Diagnostics[1] Request starting HTTP/1.1 GET https://localhost:7778/ocelot2/posts/3 - - - dbug: Ocelot.Errors.Middleware.ExceptionHandlerMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - Ocelot pipeline started dbug: Ocelot.DownstreamRouteFinder.Middleware.DownstreamRouteFinderMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - Upstream URL path: /ocelot2/posts/3 dbug: Ocelot.DownstreamRouteFinder.Middleware.DownstreamRouteFinderMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - Downstream templates: /ocelot/posts/{id} info: Ocelot.RateLimiting.Middleware.RateLimitingMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - EnableEndpointEndpointRateLimiting is not enabled for downstream path: /ocelot/posts/{id} info: Ocelot.Authentication.Middleware.AuthenticationMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - No authentication needed for path: /ocelot2/posts/3 info: Ocelot.Authorization.Middleware.AuthorizationMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - No authorization needed for upstream path: /ocelot2/posts/{id} dbug: Ocelot.DownstreamUrlCreator.Middleware.DownstreamUrlCreatorMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - Downstream URL: http://localhost:5555/ocelot/posts/3 info: Microsoft.AspNetCore.Hosting.Diagnostics[1] Request starting HTTP/1.1 GET https://localhost:7778/ocelot2/posts/5 - - - dbug: Ocelot.Errors.Middleware.ExceptionHandlerMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 Ocelot pipeline started dbug: Ocelot.DownstreamRouteFinder.Middleware.DownstreamRouteFinderMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 Upstream URL path: /ocelot2/posts/5 dbug: Ocelot.DownstreamRouteFinder.Middleware.DownstreamRouteFinderMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 Downstream templates: /ocelot/posts/{id} info: Ocelot.RateLimiting.Middleware.RateLimitingMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 EnableEndpointEndpointRateLimiting is not enabled for downstream path: /ocelot/posts/{id} info: Ocelot.Authentication.Middleware.AuthenticationMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 No authentication needed for path: /ocelot2/posts/5 info: Ocelot.Authorization.Middleware.AuthorizationMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 No authorization needed for upstream path: /ocelot2/posts/{id} dbug: Ocelot.DownstreamUrlCreator.Middleware.DownstreamUrlCreatorMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 Downstream URL: http://localhost:5555/ocelot/posts/5 info: Ocelot.Requester.Middleware.HttpRequesterMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - 200 OK status code of request URI: http://localhost:5555/ocelot/posts/3 dbug: Ocelot.Requester.Middleware.HttpRequesterMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - Setting HTTP response message... dbug: Ocelot.Responder.Middleware.ResponderMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - No pipeline errors: setting and returning completed response... dbug: Ocelot.Errors.Middleware.ExceptionHandlerMiddleware[0] RequestId: 0HNBA3NEIQUNJ:11111111, PreviousRequestId: - Ocelot pipeline finished info: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.1 GET https://localhost:7778/ocelot2/posts/3 - 200 84 application/json;+charset=utf-8 404.7256ms info: Microsoft.AspNetCore.Hosting.Diagnostics[16] Request reached the end of the middleware pipeline without being handled by application code. Request path: GET https://localhost:7778/ocelot2/posts/3, Response status code: 200 info: Ocelot.Requester.Middleware.HttpRequesterMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 200 OK status code of request URI: http://localhost:5555/ocelot/posts/5 dbug: Ocelot.Requester.Middleware.HttpRequesterMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 Setting HTTP response message... dbug: Ocelot.Responder.Middleware.ResponderMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 No pipeline errors: setting and returning completed response... dbug: Ocelot.Errors.Middleware.ExceptionHandlerMiddleware[0] RequestId: 0HNBA3NEIQUNK:AAAAAAAA, PreviousRequestId: 0HNBA3NEIQUNJ:11111111 Ocelot pipeline finished info: Microsoft.AspNetCore.Hosting.Diagnostics[2] Request finished HTTP/1.1 GET https://localhost:7778/ocelot2/posts/5 - 200 128 application/json;+charset=utf-8 347.2607ms info: Microsoft.AspNetCore.Hosting.Diagnostics[16] Request reached the end of the middleware pipeline without being handled by application code. Request path: GET https://localhost:7778/ocelot2/posts/5, Response status code: 200
Technical Facts¶
Every log record has these 2 properties:
RequestIdrepresents ID of the current request as plain string, for example0HNBA3NEIQUNJ:00000001.PreviousRequestIdrepresents ID of the previous request.
As an
IOcelotLoggerinterface object is injected into the constructors of service classes, the current default Ocelot logger (theOcelotLoggerclass) retrieves these two properties from theIRequestScopedDataRepositoryservice.
Performance [1]¶
Here is a quick recipe for your production environment to achieve top performance.
You need to ensure the minimum log level is Critical or None. Nothing more!
Having top logging performance means having fewer log records written by the logging provider. So, the logs should be pretty empty.
Anyway, during the initial period after a version release to production, we recommend monitoring the system and the current version’s app behavior by specifying the minimum log level as Error.
If the release engineer ensures the stability of the version in production, then the minimum log level can be increased to Critical or None to achieve top performance.
Technically, this will disable the logging feature entirely.
Benchmarks¶
We currently have two types of benchmarks:
SerilogBenchmarkswith Serilog logging to a file. See theConfigureLoggingmethod withlogging.AddSerilog(_logger).MsLoggerBenchmarkswith MS default logging to the MS Console. See theConfigureLoggingmethod withlogging.AddConsole().
Benchmark results largely depend on the environment and hardware on which they run. We are pleased to invite you to run logging benchmarks on your machine by following the instructions below.
Open PowerShell or Command Prompt console
Build the Ocelot solution in Release mode:
dotnet build --configuration ReleaseGo to the
test\Ocelot.Benchmarks\bin\Release\folderChoose the .NET version by changing the folder, for example, to
net9.0Run benchmarks:
.\Ocelot.Benchmarks.exeRun
SerilogBenchmarksorMsLoggerBenchmarksby pressing the appropriate number of a benchmark (5 or 6), then press Enter.Wait for 3+ minutes to complete the benchmark and get the final results.
Read and analyze your benchmark session results.