-
Notifications
You must be signed in to change notification settings - Fork 464
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Add CA1873: Avoid potentially expensive logging #7290
base: main
Are you sure you want to change the base?
Conversation
This analyzer detects calls to 'ILogger.Log', extension methods in 'Microsoft.Extensions.Logging.LoggerExtensions' and methods decorated with '[LoggerMessage]'. It then checks if they evaluate expensive arguments without checking if logging is enabled with 'ILogger.IsEnabled'.
// Check the argument value after conversions to prevent noise (e.g. implicit conversions from null or from int to EventId). | ||
if (IsPotentiallyExpensive(argument.Value.WalkDownConversion())) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is a bit of a deviation from the description in the runtime issue, but without this, there would be a lot of noise.
The following lines would be flagged:
void M(ILogger logger, EventId eventId, Exception exception, Func<object, Exception, string> formatter)
{
logger.Log(LogLevel.Trace, eventId, null, exception, formatter);
logger.Log(LogLevel.Trace, 0, "literal", exception, formatter);
}
// Implicit params array creation is treated as not expensive. This would otherwise cause a lot of noise. | ||
or IArrayCreationOperation { IsImplicit: true, Initializer.ElementValues.IsEmpty: true } |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Same here, without this, all log calls that take a params array would always be flagged, even if they do not capture anything, e.g.:
void M(ILogger logger)
{
logger.LogInformation("literal");
}
var conditionInvocations = conditional.Condition | ||
.DescendantsAndSelf() | ||
.OfType<IInvocationOperation>(); | ||
|
||
// Check each invocation in the condition to see if it is a valid guard invocation, i.e. same instance and same log level. | ||
// This is not perfect (e.g. 'if (logger.IsEnabled(LogLevel.Debug) || true)' is treated as guarded), but should be good enough to prevent false positives. | ||
if (conditionInvocations.Any(IsValidIsEnabledGuardInvocation)) | ||
{ | ||
return true; | ||
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
As stated in the comment, this is not perfect, but should be good enough to prevent false positives.
return AreInvocationsOnSameInstance(logInvocation, invocation) && IsSameLogLevel(invocation.Arguments[0]); | ||
} | ||
|
||
static bool AreInvocationsOnSameInstance(IInvocationOperation invocation1, IInvocationOperation invocation2) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
A variation of this is used in other analyzers. I think this could be a good candidate for another extension method.
[Fact] | ||
public async Task WrongLogLevelGuardedWorkInLog_ReportsDiagnostic_CS() | ||
{ | ||
string source = """ | ||
using System; | ||
using Microsoft.Extensions.Logging; | ||
|
||
class C | ||
{ | ||
void M(ILogger logger, EventId eventId, Exception exception, Func<string, Exception, string> formatter) | ||
{ | ||
if (logger.IsEnabled(LogLevel.Critical)) | ||
logger.Log(LogLevel.Trace, eventId, [|ExpensiveMethodCall()|], exception, formatter); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I was wondering if we should report another diagnostic if the log level does not match, as this is most likely a bug.
[Fact] | ||
public async Task WrongInstanceGuardedWorkInLog_ReportsDiagnostic_CS() | ||
{ | ||
string source = """ | ||
using System; | ||
using Microsoft.Extensions.Logging; | ||
|
||
class C | ||
{ | ||
private ILogger _otherLogger; | ||
|
||
void M(ILogger logger, EventId eventId, Exception exception, Func<string, Exception, string> formatter) | ||
{ | ||
if (_otherLogger.IsEnabled(LogLevel.Trace)) | ||
logger.Log(LogLevel.Trace, eventId, [|ExpensiveMethodCall()|], exception, formatter); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Another candidate for a diagnostic: Checking the wrong logger instance.
cc @stephentoub @Youssef1313 (thanks for providing the prototype 👍) |
Codecov ReportAttention: Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #7290 +/- ##
==========================================
+ Coverage 96.49% 96.51% +0.02%
==========================================
Files 1443 1445 +2
Lines 345799 348926 +3127
Branches 11374 11414 +40
==========================================
+ Hits 333665 336779 +3114
+ Misses 9251 9250 -1
- Partials 2883 2897 +14 |
Thanks. The LoggerExtensions.cs ones are all false positives in that we'll want to suppress them, but that's also effectively the implementation of logging rather than consumption of logging, and we frequently have to suppress rules in such implementations. The others for runtime look like valid diagnostics. |
{ | ||
void M(ILogger logger, EventId eventId, Exception exception, Func<string, Exception, string> formatter) | ||
{ | ||
logger.Log(LogLevel.Debug, eventId, [|nameof(logger)|], exception, formatter); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Isn't nameof
free at runtime?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
IIRC I used the description from the runtime issue:
Analyzer would detect when "work" is being done in an argument call to an ILogger logging method. This basically boils down to anything other than a literal-expression, local-expression, parameter-expression, field-expression, property-expression, or indexer-expression (potentially recursively applied).
I think excluding the nameof
expression is in the spirit of the rule (i.e. no work is done in the log call).
{ | ||
void M(ILogger logger, EventId eventId, Exception exception, Func<int, Exception, string> formatter, int input) | ||
{ | ||
logger.Log(LogLevel.Debug, eventId, [|input++|], exception, formatter); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
In this case, wrapping the log call with a check would change behaviour. Maybe the increment is needed.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We could exclude postfix increment and decrement.
{ | ||
void M(ILogger logger, EventId eventId, Exception exception, Func<int, Exception, string> formatter) | ||
{ | ||
logger.Log(LogLevel.Debug, eventId, [|default|], exception, formatter); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Isn't default
free at runtime?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Isn't
default
free at runtime?
For reference types.
For value types, it depends on the type. But it should, in general, be "free".
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Right, I mean, there's no overhead in passing the value. It's just zeroed memory. I don't think it warrants a diagnostic.
Here's a sharplab.io showing default
and nameof
are both compile-time constant values.
private static void Foo(params object?[] objects) {}
public static void M()
{
Foo(default(int), default(object), nameof(Foo));
}
...M()
becomes...
object[] array = new object[3];
array[0] = 0; // don't set array[1] as it's already null
array[2] = "Foo";
Foo(array);
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For this code, value types will be boxed.
Wither being boxed or passed by value, big value types may be a problem.
I know you're not thinking of those, but they are out there.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If the original concern here was boxing (having that info in the diagnostic message, or at least in a comment would be helpful) then it should only apply to value types. I'd like to hear @mpidash's motivation here.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
My motivation was the same as in #7290 (comment). I think we could also exclude default
; there may be places where it is not 100% free, but the same could be argued for properties and we exclude those as well.
Fixes dotnet/runtime#78402.
This analyzer detects
ILogger.Log
,Microsoft.Extensions.Logging.LoggerExtensions
and[LoggerMessage]
and flags them if they evaluate expensive arguments without checking if logging is enabled with
ILogger.IsEnabled
.There are 12 findings in
dotnet/runtime
(8 of them inMicrosoft.Extensions.Logging.Abstractions
which will probably disable this warning), 157 findings indotnet/roslyn
and 497 indotnet/aspnetcore
(including testing code).I skimmed through them and could not find any false positives.