Skip to content
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

CA2254 Should not apply when log message template is a resource string. #5626

Open
thomas-erdoesi opened this issue Oct 13, 2021 · 70 comments
Open
Labels
Area-Microsoft.CodeAnalysis.NetAnalyzers Bug The product is not behaving according to its current intended design False_Positive A diagnostic is reported for non-problematic case
Milestone

Comments

@thomas-erdoesi
Copy link

thomas-erdoesi commented Oct 13, 2021

Diagnostic ID: [CA2254]

The code analyzer info message "The logging message template should not vary between calls to 'LoggerExtensions.LogDebug(ILogger, string?, params object?[])' appears when using a message template that is defined in a resource file.

Examples:
logger.LogDebug(MyResources.MyMessageTemplate, param1, param2,...);
logger.LogDebug(localizer["MyMessageTemplate"], param1, param2,...);

Resource strings are culture specific "constants", so it might make sense to treat properties of classes generated from .resx files and values of type LocalizedString as constants.

@nielstanghe
Copy link

Having the same issue since updating to Visual Studio 2022

@tbalakpm
Copy link

For me same issue since updated to .net 6.0

@jmihalich
Copy link

jmihalich commented Nov 29, 2021

Same issue here, but i get it with a direct inline string with .net 6.0:

logger.LogDebug($"my message with {myparam}");

image

@mavasani mavasani added Bug The product is not behaving according to its current intended design False_Positive A diagnostic is reported for non-problematic case Area-Microsoft.CodeAnalysis.NetAnalyzers labels Nov 29, 2021
@mavasani mavasani added this to the .NET 7.x milestone Nov 29, 2021
@Sour-Codes
Copy link

image
I am targeting net7.0 and net6.0. Builds just fine minus the warning.

@systemidx
Copy link

systemidx commented Dec 14, 2021

I also get this on a basic global exception handler middleware for MVC.

    public class GlobalExceptionMiddleware
    {
        private readonly RequestDelegate _next;
        private readonly ILogger<GlobalExceptionMiddleware> _logger;

        public GlobalExceptionMiddleware(RequestDelegate next, ILogger<GlobalExceptionMiddleware> logger)
        {
            _next = next;
            _logger = logger;
        }

        public async Task Invoke(HttpContext httpContext)
        {
            try
            {
                await _next(httpContext);
            }
            catch (Exception ex)
            {
                _logger.LogError(ex, ex.Message);
                throw;
            }
        }
    }

The message occurs on the _logger.LogError(ex, ex.Message); line.
Targeting .NET 6.

@arthuredgarov
Copy link

@systemidx, the ex.Message is not a static string, so the warning you are getting is not a false positive.

@systemidx
Copy link

@arthuredgarov You're right, it's not. It's not a 100% analogue to the OP's issue of providing a static string from a resource file, but I still get CA2254 for some reason when pushing ex and ex.Message to ILogger.LogError. This didn't happen before the last VS2022 update on my end.

@arthuredgarov
Copy link

arthuredgarov commented Dec 14, 2021

@systemidx, well, yes, that's what this analyzer rule stands for. You are providing a non-static string as the message parameter and getting the corresponding warning. The message parameter is intended to be a format string, you can check that in the method summary. By the way, if you are using the default implementation of the ILogger interface - you should not pass the ex.Message since the exception message will be logged and displayed from the ex instance you pass as the first parameter. Doing the way you do will lead to exception message duplicating in your logs. Instead, you could provide a more informative message describing the exception that occurred. If you don't want to do that, you could just define your own extension method that will call _logger.LogError(ex, "");.
For example:

public static void LogException(this ILogger logger, Exception ex)
    => logger.LogError(ex, "");

@arthuredgarov
Copy link

@Sour-Codes, the same for you. Please check my comment above.

@simkin2004
Copy link

@arthuredgarov : In a strict sense of the definition "static", you are correct.

Pragmatically, the point of this analyzer is to determine whether the code is building a string to use in the logger. A string defined in a Resource file is a static string in the sense that its value -for a given Culture- cannot change at run-time.

Providing log entries for the developer/ops person in the appropriate language is important, unless you believe that Microsoft should deliver all of its log messages in English only or Chinese only or French only.

Until this analyzer message provides the pragmatic value of preventing developers from building strings to pass into loggers, it will be suppressed as a false positive by many in the community.

@SoftCircuits
Copy link

I get the same warning with the following.

Logger.LogInformation($"**** Starting {ApplicationInfo.Description} ****");

What's strange is that I get the exact same warning this.

string start = $"**** Starting {ApplicationInfo.Description} ****";
Logger.LogInformation(start);

But I don't get the warning with this.

Logger.LogInformation("**** Starting ApplicationInfo.Description ****");

The error message makes no sense to me. I can't make heads or tails of this.

@kcaswick
Copy link

I get the same warning with the following.

Logger.LogInformation($"**** Starting {ApplicationInfo.Description} ****");

The warning wants you to change to this:

Logger.LogInformation("**** Starting {0} ****", ApplicationInfo.Description);

That's harder to read though.. my preference would be the compiler turns string interpolation into a format string and parameters when passed to a function like this, or with some extra character.

@SoftCircuits
Copy link

@kcaswick Thanks for an explanation of this warning. The wording doesn't seem to say what you said. They should have you write the warning. ;-)

Yeah, in this case the parameter has absolutely nothing to do with anything I want to be part of logging. I'm just trying to use string interpellation to build a string. The compiler is being too smart here.

@Trolldemorted
Copy link

The warning wants you to change to this:

Any idea why the latter would be better? It is not as readable as the former and they should be equally fast.

@kcaswick
Copy link

Any idea why the latter would be better? It is not as readable as the former and they should be equally fast.

Probably this: (longer explanation at https://stackoverflow.com/a/49434820/20068)

If you use the {0} format, the argument won't get translated into a string until after the logging framework has decided whether or not to emit this message, whereas the {myVar} format is translated to a string before the function is entered.

Also it is a problem if you use structured rather than plain text logging: https://habr.com/en/post/591171/

@Trolldemorted
Copy link

Probably this: (longer explanation at https://stackoverflow.com/a/49434820/20068)

Thanks! Could we get the gist of that into the warning? I think I am not the only one who reacted with "but why though" at first.

@maryamariyan
Copy link
Member

maryamariyan commented Feb 9, 2022

As with LogError, LogDebug, LogInformation, etc. the best practice is to move away from using interpolated strings as input string. So precisely the way explained in #5626 (comment),

Logger.LogInformation($"**** Starting {ApplicationInfo.Description} ****");

needs to change to

Logger.LogInformation("**** Starting {AppDescription} ****", ApplicationInfo.Description);

The purpose of CA2254 is diagnostics is to not have mutable strings logged. So an input like:

logger.LogDebug($"my message with {myparam}");

needs to change to

logger.LogDebug("my message with {MyParamInMessageTemplate}", myparam);

The benefit to not using string interpolation is that allows for proper structured logging to be done by the framework so for example for a log method taking LogInformation("Welcome to {city} {province}", city, province), the framework would be able to capture the following state that it wouldn't otherwise if you used string interpolation:

{
  "EventId": 13,
  "LogLevel": "Information",
  "Category": "LoggingExample",
  "Message": "Welcome to Vancouver BC!",
  "State": {
    "Message": "Welcome to Vancouver BC!",
    "City": "Vancouver",
    "Province": "BC",
    "{OriginalFormat}": "Welcome to {city} {province}!"
  }
}

@SoftCircuits
Copy link

@maryamariyan I understand the intent. But not every string I log needs splitting up into different fields. Sometimes I'm just trying to log a string from different sources. There is absolutely no benefit that I can see from treating the application description any differently than the rest of the string.

@maryamariyan
Copy link
Member

@maryamariyan I understand the intent. But not every string I log needs splitting up into different fields. Sometimes I'm just trying to log a string from different sources. There is absolutely no benefit that I can see from treating the application description any differently than the rest of the string.

Thanks for the feedback. If it feels onerous to do changes on the developer side in some cases then maybe the diagnostics needs to be revisited. e.g. perhaps we could consider to change the diagnostic severity from warning to information. Your case or the others represented above are not really false positives. The analyzer was supposed to catch them intentionally.

@naughtyGitCat
Copy link

that feels make c# logging code verbose like java, I think it makes code hard to read, willing to rollback

@arthuredgarov
Copy link

@maryamariyan,

or the others represented above are not really false positives.

OP report as well? I mean, in case I have the following code I will get CA2254 too:

//Somewhere in .resx file
MyResource.Greeting = "Welcome to {city} {province}!"

//Logging itself
LogInformation(MyResource.Greeting, city, province)

@maryamariyan
Copy link
Member

maryamariyan commented Feb 16, 2022

The reason we don't recommend using interpolated strings with logging APIs is the message templates are meant to help with producing structured log messages. This doc https://messagetemplates.org/ goes over message templates.


that feels make c# logging code verbose like java, I think it makes code hard to read, willing to rollback

We're open to revisiting this and would like to better understand developer expectations before proceeding with next actions here. To do this, let's go through another logging example (this time not using LogError/LogWarning but the new logging source generator feature instead). Consider the new logging source generator feature presented in here, with the sample usage code below:

public static partial class Log
{
    [LoggerMessage(
        EventId = 0,
        Level = LogLevel.Critical,
        Message = "Could not open socket to `{hostName}`")]
    public static partial void CouldNotOpenSocket(
        ILogger logger, string hostName);
}

With this sample usage, you'd see the Message is the message template and arguments to the method would be the variables you pass to it. The message template that the developer places in the LoggerMessage annotation as Message is what is supposed to not vary between calls. This way the message template gets written once and for every usage the developer only calls this method passing down any variables as argument to the log method.


@Youssef1313 @333fred what is your take on how the analyzer should behave for the use case below presented in comment #5626 (comment) above? I first take is this would not be acceptable.

//Somewhere in .resx file
MyResource.Greeting = "Welcome to {city} {province}!"

//Logging itself
LogInformation(MyResource.Greeting, city, province)

@MisinformedDNA
Copy link

The analyzer rule is useful IMO, but there should be a code fix and improved documentation. This is way too little information:

image

@mavasani
Copy link
Member

@gewarren for documentation improvement

@agm1981
Copy link

agm1981 commented Jul 27, 2022

Apologies for (maybe) veering more off-topic... If one needs highly structured data for later analysis, why not just log it into a database? Is that what "structured logging" is trying to recreate?

Having said that, I did discover/realize, thanks to this issue, that the Serilog Console logger will color-code replacements based on their data type... so that's pretty neat (even in .NET 5).

But the actual reason I'm switching my code to non-interpolated log strings, which I should have realized a lot sooner (I thought .net "had my back" lol), is contained in this snip from the previously-quoted SO answer:

If you use the {0} format, the argument won't get translated into a string until after the logging framework has decided whether or not to emit this message, whereas the {myVar} format is translated to a string before the function is entered.

I certainly prefer "lazy" logging any day. IMHO any warnings should point that out.

Database logging is not a solution. It will degrade your application performance to a crawl and it will increase your actual hosting costs and network traffic.

Imagine a simple scenario where your systems picks up a record from database, process it and saves the output in another table. That is only two database trips, now if your process is doing anything and you will start logging parameters and possible values and temporary states. If you have to go to the database every time to save that log, just forget it, you are done.
On most of my apps, I do exponentially more log calls than database calls, because on cloud computing you can't debug on the server, so you have to log methods and their parameters, so you can then reproduce any errors.
Aws and azure offer high throughput logging mechanism that won't hurt your performance.

@agm1981
Copy link

agm1981 commented Jul 27, 2022

Back to the topic. Don't change the current behavior. Structured logging is the better solution and the compiler should hint at people so they change their habits little by little.

@qsdfplkj
Copy link

qsdfplkj commented Jul 31, 2022

One thing I personally I like to do is:

logger.LogError(ex, ex.Message);

This of course triggers the warning. Rewriting this to avoid the warning kind of defeats the purpose of the warning.

logger.LogError(ex, "ExceptionMessage: {exceptionMessage}", ex.Message); 

@arthuredgarov
Copy link

One thing I personally I like to do is:

logger.LogError(ex, ex.Message);

@qsdfplkj, please look at my comment above.

@bronumski
Copy link

@qsdfplkj as @arthuredgarov said, let the framework do the job for you. It knows what to do with an exception, you can set up log templates to include the message in the log. Better yet structured logging libraries (serilog) and tools (seq) can render the exception much more clearly. Additionally if you are logging an exception at the debug level and have disabled debug the app will not waste time getting the log message in order to render it.

@qsdfplkj
Copy link

It was me bring clever/lazy to write a proper log message. But it makes sense now.

@skrabbe001
Copy link

skrabbe001 commented Aug 2, 2022 via email

@skrabbe001
Copy link

skrabbe001 commented Aug 2, 2022 via email

@skrabbe001
Copy link

skrabbe001 commented Aug 2, 2022 via email

@eerhardt
Copy link
Member

eerhardt commented Aug 5, 2022

Is anyone seeing CA2254 as an actual warning? The default severity for that rule is "info", which means it shows up under "Messages" in your error list, but it shouldn't be emitted as an actual warning:

image

If you are getting warnings, can you post a picture of it, and what your editor config (if any) looks like?

@qsdfplkj
Copy link

qsdfplkj commented Aug 17, 2022

So why now #pragma warning disable CA2254 causes an IDE0097 remove unnecessary suppression? First I had to add it now I have to remove it.

image

@agm1981
Copy link

agm1981 commented Aug 17, 2022

pragma warning only deals with warnings.

To be clear, you are still doing something considered inappropriate, that is why it is informing you.

@qsdfplkj
Copy link

qsdfplkj commented Aug 18, 2022

Ok... adding an empty .editorconfig causes this. (So I guess .editorconfig is not additive but it replaces everything).

@buyaa-n buyaa-n modified the milestones: .NET 7.x, vNext Aug 24, 2022
@ygoe
Copy link

ygoe commented Oct 18, 2022

I'm not sure what this message does at all, because it even applies when there are no parameters at all. There is nothing to resolve here, I cannot do anything to remove that message:

logger.LogError(ex, ex.Message);

PS: This is a simplified repro example. My actual code uses an extension method that returns a more useful message:

logger.LogError(ex, ex.GetRecursiveMessage());

@changhuixu
Copy link

You can do this _logger.LogError(ex, "{m}", ex.Message);
Though, I agree that it doesn't look as elegant as _logger.LogError(ex, ex.Message);

I'm not sure what this message does at all, because it even applies when there are no parameters at all. There is nothing to resolve here, I cannot do anything to remove that message:

logger.LogError(ex, ex.Message);

PS: This is a simplified repro example. My actual code uses an extension method that returns a more useful message:

logger.LogError(ex, ex.GetRecursiveMessage());

@ygoe
Copy link

ygoe commented Oct 18, 2022

You can do this _logger.LogError(ex, "{m}", ex.Message); Though, I agree that it doesn't look as elegant as _logger.LogError(ex, ex.Message);

Sure I could, but why would I want to do that? Isn't the simplest solution the best? What's the benefit of this additional complexity at all?

@mickelsonmichael
Copy link

@ygoe in your contrived example, the ex.Message will be logged anyway by most common formats, meaning you will be outputting the message twice.

I'm not sure what your ex.GetRecursiveMessage() does, but it would make a lot of sense to make an ILogger.LogRecursiveException(Exception) extension method to clean that code up. Then you could either avoid the flag entirely (depending on the implementation), or you can simply ignore it on the singular line using #pragma warning disable CA2254 // Template should be a static expression, and won't need to repeat yourself.

@ygoe
Copy link

ygoe commented Oct 18, 2022

@mickelsonmichael That method collects the messages of inner exceptions all into a single string. Often, the message of the caught exception tells nothing more than that there was any error and details can be found in the inner exceptions. Such a log message is then useless. To avoid that, my extension method generates more useful messages.

I also have other examples, like:

logger.LogError(ex, "The XYZ operation could not be completed. " + ex.GetRecursiveMessage());

This would basically add another level of error messages on top of the exception stack. It gives them a context that they might not have, and makes it really easy to understand an error from a single log entry. (I also log the exception details but sometimes they are simply unavailable from the log, depending on how it's accessed.)

I guess I'll shut down that warning on a global level. At least until somebody showed me a good example why I would want to follow it. It still seems pointless and arbitrary to me and provides no benefit at all. It's even less readable and more error-prone than an interpolated string which puts the parameters right where they belong, instead of counting arguments and eventually mixing them up.

BTW, setting the severity to NONE from the quick actions has no effect at all. No files were changed and the warning doesn't go away. Is there a problem with the code fixes? Typing the suggested fix manually into my .editorconfig file resolves the issue immediately:

# Don't suggest using ILogger placeholders and arguments
dotnet_diagnostic.CA2254.severity = none

I'm going to include that in my global defaults.

@tarekgh
Copy link
Member

tarekgh commented Oct 21, 2022

@Dean-NC it is not a warning it is just info.

@simkin2004
Copy link

90% of the comments on this thread are tangential to the original request.

I (and the original poster) still have not received a response about how to go about handling logging in different languages using Resource files and still complying with this rule.

If that is not possible, then update the documentation to make sure anyone with i18n or l10n requirements for that logging are properly informed to disable this rule.

@tarekgh
Copy link
Member

tarekgh commented Nov 8, 2022

@simkin2004 we are keeping this issue open to see if we can do something for the resource's cases.

@asimontsev
Copy link

I like the idea of structured logging, however, I believe it should be applied only to certain log levels, say, Information and higher. I don't think that it is worthy to do it for Debug and Trace level.

In my understanding, using structured logs are like creating a table with columns for each placeholder names. It means I should have consistent placeholder names through the entire project (which is absolutely fine), however it does not seem realistic for debug information (which may be quite unique for each particular method). As a result, I can end up with hundreds or thousands of "columns" in such "table".

Or my understanding is wrong here? If not, any chance to make it possible to fine tune the warning strategy depending on a log level?

@maryamariyan maryamariyan removed their assignment Jan 9, 2023
@peabnuts123
Copy link

A lot has already been said in this thread so I'll just add what I feel hasn't been said: Logging is not always structured. For my Web API or console app, logs are just going into some kind of text output. I just want to output data so I can see what's happening. It seems aggressive to me to suggest all developers should use structured logging in all use-cases. It is my opinion that using a formatted string is less readable and therefore undesirable. When my project gets sophisticated enough that I'll need to actually query my logs, that trade-off will be more valuable, and I can make that change.

Since it's clear there is a lot of different opinions and needs represented by this issue, is there a way that I can disable this rule for my whole solution? It's obviously infeasible to disable it at every location I'm logging something. Some kind of entry in my csproj or something? I personally do not agree with it, so I should be able to opt-out.

@Youssef1313
Copy link
Member

@peabnuts123 You can disable it for sure. In .editorconfig, add dotnet_diagnostic.CA2254.severity = none

@Gladskih
Copy link

Gladskih commented Jan 15, 2023

Isn't the main goal of structured logging to have logs auto processible without parsing?
It is not about making an app to build a human readable string from data at all! If we need a data we shall just pass it as part of event. We shall not expect logging framework to include data back to message of the event. Messing with templates was so wrong way that I cannot understand how the community has not rejected the idea yet (and for so long).
So warning should be deleted of course. And log system should support providing data without including into message (dotnet/runtime#35995). Message is just part of event in the same way as any other data.

@TimothyByrd
Copy link

For places where I want to log a message I do something like this

/// <summary>
/// To get around CA2254
/// </summary>
public const string LogMessage = "{Message}";

string message = <comes from somewhere>;
logger.LogInformation(LogMessage, message);
// instead of logger.LogInformation(message);

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area-Microsoft.CodeAnalysis.NetAnalyzers Bug The product is not behaving according to its current intended design False_Positive A diagnostic is reported for non-problematic case
Projects
None yet
Development

No branches or pull requests