#1744 Avoid calls to 'Logger.Log' if LogLevel not enabled in appsettings.json

[ggnaegi]

Closes #1744

• 1744

Changing string parameter of IOcelotLogger methods to Func<string>, modifying AspDotNetLogger.cs, only one main method and verifying if LogLevel is enabled. If log level isn't enabled, then return.

Proposed Changes

• Using Func<string> instead of string as parameter for log methods, avoiding unneeded string operations
• Checking if the LogLevel is enabled before 1) Calling ILogger.Log method; 2) calling Func<string>.Invoke().
• Code refactoring, only one method for Log writing in AspDotNetLogger.cs

private void WriteLog(LogLevel logLevel, Func<string> messageFactory, Exception exception = null)
{
    if (!_logger.IsEnabled(logLevel))
    {
        return;
    }

    var requestId = GetOcelotRequestId();
    var previousRequestId = GetOcelotPreviousRequestId();

    var state = $"requestId: {requestId}, previousRequestId: {previousRequestId}, message: {messageFactory.Invoke()}";

    _logger.Log(logLevel, default, state, exception, _func);
}

Benchmarks:

@raman-m @RaynaldM Ok, after the refactoring, I realized that the benchmark, per design, has no log level defined. If I change the condition to

if (_logger.IsEnabled(logLevel))
        {
            throw new Exception("min si c'est génial");
        }

then it will run without throwing exceptions. It means IsEnabled is never true there. Ok, since I know that, and I have a wonderful unique wrapper method, I can get the the benchmarks values nearly without any logs activities. Figure 1: Benchmark with empty WriteLog Wrapper method

Now, let's put back the new WriteLog method implementation. Performance is not as good as no logs activities at all, but the performance is still great. Figure 2: Benchmark with new WriteLog Wrapper method

We can now try to log everything - at least call the log method Figure 3: Log everything

And a final check, with the current develop branch Figure 4: Current develop branch benchmark

As you can see, we have similar results for 3 and 4.

Discussion

• 1736

[ggnaegi]

I do not approve this time. Where are the tests? My concerns:

• Removing old signature methods is wrong until we'll find a solution to recognize string constants and string building
• No applied fix by @RaynaldM using #if DEBUG directive, which is main goal

We can keep the old signature methods, you're right, if it's a string constant, the factory is useless. We would aswell keep the backward compatibility.

[raman-m]

Gui, Could you explain me Benchmarks results please? Do we need to compare Median values, right? I see that Ray's approach improves performance decreasing value by ~200 nanoseconds, from 1300 down to 1000. But your design approach decreased the value in 2+ times, down to ~550 nanoseconds from ~1300 nanoseconds. This is the perfect result! 🎉 Strong argument to use factory methods! 👍 😍

[raman-m]

From screenshots I didn't get it what benchmarks did you run? Have you prepared special benchmark classes or used old ones? How to run benchmarks locally?

[raman-m]

Oh, and I've missed one thing in code review... You haven't tested the case when LogLevel is unknown to prove that optimization and the feature works in real, am I wrong? We need to write a few acceptance tests... Adding this point to code review results...

[raman-m]

@ggnaegi Gui, let me focus on minor release for documentation... I've reviewed this PR, and I'll get back to you after the docs release... So, I'll be silent from now...

[ggnaegi]

Oh, and I've missed one thing in code review... You haven't tested the case when LogLevel is unknown to prove that optimization and the feature works in real, am I wrong? We need to write a few acceptance tests... Adding this point to code review results...

Yes, I will add the test cases.

[ggnaegi]

Oh, and I've missed one thing in code review... You haven't tested the case when LogLevel is unknown to prove that optimization and the feature works in real, am I wrong? We need to write a few acceptance tests... Adding this point to code review results...

Same tests as @RaynaldM, you can start them locally from test/Ocelot.Benchmarks. I will provide a new Benchmark for the request mapper. It's on going...

[ggnaegi]

@raman-m I think, the code is now ready for review, I have added several unit tests - verifying if invoke is called, verifying if log has been called - and acceptance tests - verifying that the log level corresponds to the appsettings.json -

[ggnaegi]

Long code requires more improvement. Thank you for writing tests! I will review maybe later. Try to compress them and use DRY approach: more small helpers.

And I will run benchmarks later too... I have a concern about benchmarks: Why do you test Serilog injected implementation? In my opinion, we need to test standard MS ASP.NET logger implementations first.

It's the case in the unit tests. I'm using serilog in the acceptance tests. I could have created an In memory logger though...

[raman-m]

@ggnaegi commented on Oct 28

Could we run tests for different loggers like Microsoft, Serilog etc.?

[ggnaegi]

@ggnaegi commented on Oct 28

Could we run tests for different loggers like Microsoft, Serilog etc.?

Yes, but that's again quite a bit of work...

[ggnaegi]

@raman-m changes analyzed and code updated. You can re-review

[raman-m]

This feature should be included in October's release. Going to review once again...

[raman-m]

@ggnaegi Please, check auto-merge results after the last merging of develop!

[ggnaegi]

Hello @raman-m, should be fine

[raman-m]

Could you rebase the feature branch onto ThreeMammals:develop please? OR Could you sync your fork to update develop please? And, rebase the feature branch onto develop please.

[raman-m]

The question

• Who will update docs? 😛

[ggnaegi]

The question

• Who will update docs? 😛

Well... Let rebase first

[raman-m]

@ggnaegi commented on Nov 2 Well... Let rebase first

Yeap! Please sync fork and rebase! 🙏

[ggnaegi]

@ggnaegi commented on Nov 2 Well... Let rebase first

Yeap! Please sync fork and rebase! 🙏

@raman-m Ok, first, the code is cleaner than before, there is only one line of code that could be of concern but that's not ocelot's responsability. If someone doesn't want any logging, then, with this code design he could even choose not to call the ILogger.Log method (otherwise I should follow the same approach as Raynald with pre-processors)

[ggnaegi]

Gui, I have a concern regarding Microsoft and Serilog user scenarios in benchmarks. It will be better to prepare both or even more benchmarks to play with these all scenarios. That will allow you to tune and refactor current Logging feature to adjust to all MS and non-MS user scenarios. You have a couple of days, because at this moment we are not ready to deliver October's release with this and another features. It will take 2-3 days more to prepare... 😢 So, you have a time to work on this PR more.

As I wrote, it's not our responsability, now the code is clean, if you want to shutdown the logging, then you can do it easily. Before you had to put some pre-processors all over the place. I'm a bit surprised by your reaction.

We could add a global variable for the complete logging shutdown? @RaynaldM @raman-m what do you think? Or enforce a global minimum logging level with our own filter and add it to the global configuration. But this would mean more work...

Even Microsoft writes:

It's a good practice to call ILogger.IsEnabled within ILogger.Log implementations since Log can be called by any consumer, and there are no guarantees that it was previously checked. The IsEnabled method should be very fast in most implementations.

https://learn.microsoft.com/en-us/dotnet/core/extensions/custom-logging-provider

[raman-m]

Gui, Thanks for branch rebasing! But we have build error 😢 The problem with Ocelot.UnitTests.Polly.PollyQoSProviderTests.should_throw_and_before_delay_should_not_allow_requests unit test...

[raman-m]

@ggnaegi commented on Nov 3 If someone doesn't want any logging, then, with this code design he could even choose not to call the ILogger.Log method (otherwise I should follow the same approach as Raynald with pre-processors)

Hush! No, we won't go with Raynald's approach 😃 Your solution is better!

[ggnaegi]

Gui, we have build error! The problem with Ocelot.UnitTests.Polly.PollyQoSProviderTests.should_throw_and_before_delay_should_not_allow_requests unit test...

Yeah, I'm still on it, I just rebased it and now will review it.

[ggnaegi]

@raman-m it's gonna be late afternoon though, sunday...

[raman-m]

@ggnaegi commented on Nov 3:

As I wrote, it's not our responsibility, now the code is clean, if you want to shutdown the logging, then you can do it easily. Before you had to put some pre-processors all over the place. I'm a bit surprised by your reaction.

Yes, code is clean. As I said, we won't go with Ray's proposal to use preprocessing directive, because your solution is solid & better. Regarding my reaction... It is not a reaction, it is more a try to understand your solution. So I need some deep dive into the code once again to understand it completely...

---

We could add a global variable for the complete logging shutdown? @RaynaldM @raman-m what do you think? Or enforce a global minimum logging level with our own filter and add it to the global configuration. But this would mean more work...

Emm.... Isn't it shut down completely if no defined log options in appsettings.json because it's requirement of this PR? 😉 Or, did you mean a feature switcher in ocelot.json?.. I believe, your idea to add global logger settings is right. We could propose Error level by default, because it is very useful even for production environments. But looks like it will be another logging feature... So, it is out of the scope of current PR and task. I do not want to delay October's release...

[raman-m]

Even Microsoft writes: Implement a custom logging provider in .NET

Thanks for sharing this link!

[raman-m]

it's gonna be late afternoon though, Sunday...

It's 🆗 Enjoy your Sunday, Gui!

[ggnaegi]

@raman-m Ok, rebase done, fixed the tests, Added MS Logger with console provider benchmarks.

[raman-m]

@RaynaldM wrote on Nov 6:

What's missing the most: I have a real problem with logs. Let me explain: sometimes there are too many of them, and often they lack precision (for example here and here: which Downstream is concern). I think it's the user app's responsibility to log (and perhaps process) warning and error logs. We're in the process of remaking an IOcelotLogger to better process logs. We'd also like to add OpenTelemetry to better track it in production.

Yeap! Sorry, I've totally missed this while merging a few days ago. Thanks for notes! Especially for QoS we need to log with Warning as a max log level, to allow to have high performance in production. In my opinion, we should not log open circuit event with Error level, but we could log with Debug/Info levels, and Warning for errors. So, does it look like best practice?

[ggnaegi]

@raman-m but we are mixing concerns... Here we are talking about the logs from qos... Maybe we could open a new issue? Because now, we are almost ready with this PR. Are the changes in qos logs part of PR too?

[raman-m]

@ggnaegi wrote on Nov 7:

@RaynaldM Well, it's the QoS bug fix we just merged to develop. Maybe you could give us a feedback about what would make sense, what would you expect as log messages in this case? I don't use the QoS since our Polly policies are implemented on the client side. As an example @raman-m asked about the logs in QoS. I didn't modify them because they were already there, but, yeah, they don't make really sense. Imho, we could just remove the two in PollyPoliciesDelegatingHandler and then foresee a centralized Exception handler. As for the Circuit Breaker onBreak we could set _logger.LogDebug the BrokenCircuitException will be thrown anyway.

Don't panic! 😄 Even multiple code reviews don't eliminate design issues. That's why I love pair programming practice for high quality products. Sorry, it was late: I've missed the thing with log levels.

---

As an example @raman-m asked about the logs in QoS. I didn't modify them because they were already there, but, yeah, they don't make really sense.

It is OK to have logging for Polly, but we have to decrease log levels. Finally, a developer can switch off QoS feature removing settings from a route. Am I right? Or QoS is still functioning without QoS options? OR What about feature switcher for logging especially for QoS ? We could add a property to QoS options model.

---

Imho, we could just remove the two in PollyPoliciesDelegatingHandler and then foresee a centralized Exception handler.

Sorry, cannot get your idea... Refactoring Exception-to-Error mapper logic? If Yes, please not in this PR! Regarding _logger.LogError like here As a compromise, we need to decrease log level down to Information/Warning. You proposed to remove logging at all. We can leave Information level here, right?

---

As for the Circuit Breaker onBreak we could set _logger.LogDebug the BrokenCircuitException will be thrown anyway.

Agree! But Debug will be pretty low level for the onBreak event, so we could log with Information/warning level? So, the level of the onBreak event should be greater than for other events: onReset and onHalfOpen. Sounds good?

[raman-m]

@ggnaegi commented

Is it so hard to decrease logging levels? Isn't it look like a compromise for all of us: you, me, and Ray?

[ggnaegi]

@ggnaegi commented

Is it so hard to decrease logging levels? Isn't it look like a compromise for all of us: you, me, and Ray?

No, ok, fine... And the two exceptions in the delegating handler?

[raman-m]

@ggnaegi Everywhere in QoS log level Error is forbidden. So, please, remove LogError! And it seems Warning level is not good too. Later we will rework logging in QoS...

[raman-m]

Gui, have you added string factories for the rest of logging lines in develop?

[RaynaldM]

@ggnaegi Everywhere in QoS log level Error is forbidden. So, please, remove LogError! And it seems Warning level is not good too. Later we will rework logging in QoS...

We are working on the suject, I'll create an new issue and make a PR next week

[ggnaegi]

Gui, have you added string factories for the rest of logging lines in develop?

I should have yeah. I checked it at least.

[raman-m]

We are working on the subject, I'll create an new issue and make a PR next week

@RaynaldM Before Oct release or after? 🤣

[RaynaldM]

We are working on the subject, I'll create an new issue and make a PR next week

@RaynaldM Before Oct release or after? 🤣

We need it in november release 😃

[raman-m]

Hi team! What's the rest of work here?

[ggnaegi]

Hi team! What's the rest of work here?

Your final review?

[raman-m]

Please, rebase feature branch, resolve merge conflicts, and I'll review...

[ggnaegi]

@raman-m Rebase done