-
Notifications
You must be signed in to change notification settings - Fork 4.9k
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
FormattedLogValues struct should be public #67577
Comments
Tagging subscribers to this area: @dotnet/area-extensions-logging Issue Detailshttps://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/FormattedLogValues.cs should be imho public. There are use cases where I want to log and return or throw same string. Would be handy to do something like:
|
Why do you need Would you please share more about the scenario in which you are have that would need the logged string to be returned? |
This issue has been marked |
Related closed PR dotnet/extensions#2814 (comment) This has been made internal before: dotnet/extensions#513 |
For example in customer facing APIs it is usually handy to return human readable error. When customer contacts about problem encountered, the first thing they send is the error message but not any traceable guids. It makes triaging customer issues much faster. |
@davidfowl @pakrym was there a strong reason to keep this internal in the PR dotnet/extensions#513 |
There wasn't a strong reason to keep it public so we made it internal. There hasn't been many great explanations as to how it's being used. |
Here we see an example where make public make a difference |
I expect that some people want it to be public because they're trying to use it in unit test assertions, e.g. with Moq: _loggerMock.Verify(
logger => logger.Log(
LogLevel.Error,
It.IsAny<EventId>(),
It.Is<It.IsAnyType<object>>(obj => ...), // This is where it would be useful to have access to the FormattedLogValues.
exception,
(Func<It.IsAnyType, Exception?, string>)It.IsAny<object>()),
Times.Once()); You can call I expect this is a common use case because until recently, I was one of those people. However, I've now realized that a much better solution to this assertion problem is actually to use Using LoggerMessage has other benefits as well. The only downside is that it requires a bit more boilerplate. |
We added a source generator to reduce/eliminate the boilerplate. See https://docs.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator |
@eerhardt @davidfowl I have another use case and that is that I have my own LoggerProvider + Logger that I want to pass information to. Example: public class MyCustomClass { }
public readonly struct CustomState {
public string Message { get; }
public MyCustomClass Data { get; }
public CustomState(string message, MyCustomClass data) {
Message = message;
Data = data;
}
public override string ToString() => Message;
}
public static class ILoggerExtensions {
public static void LogCritical(this ILogger logger, string message, MyCustomClass data) {
logger.Log(LogLevel.Critical, null, new CustomState(message, data));
}
public static void LogCritical(this ILogger logger, Exception exception, string message, MyCustomClass data) {
logger.Log(LogLevel.Critical, exception, new CustomState(message, data));
}
private static void Log(this ILogger logger, LogLevel logLevel, Exception exception, CustomState customState) {
logger.Log(logLevel, 0, customState, exception, (state, exception) => state.Message);
}
}
public class CustomLogger : ILogger
{
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
if (state is CustomState customState)
{
}
else
{
}
}
} My problem is that I can't use this extension method overload: I can't because that overload receives directly "string message, params object?[] args" and I would lose my custom state on the way and I wouldn't get to my custom logger... If I had access to: https://github.com/dotnet/runtime/blob/v7.0.0/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/FormattedLogValues.cs I understand that I could do it myself without that overload. |
+1 for making it public. I'm learning the internals of ASP.NET Core logging and it's the type of the event my custom logger receives. Not a too strong reasoning but still. |
+1 for making it public or for alternatively making the logger easier to mock. |
+1 for making it public for unit testing purposes |
+1 for making it public for unit testing purposes.. But Work around for unit tests: var mock = new Mock<ILogger>();
mock.Setup(x => x.Log(
LogLevel.Information,
It.IsAny<EventId>(),
It.IsAny<It.IsSubtype<IReadOnlyList<KeyValuePair<string, object?>>>>(),
It.IsAny<Exception>(),
It.IsAny<Func<It.IsSubtype<IReadOnlyList<KeyValuePair<string, object?>>>, Exception?, string>>()))
.Callback
<LogLevel,
EventId,
object,
Exception,
Delegate>
((logLevel, eventId, state , exception, formatter) =>
{
//at this point you can call ToString from state and Assert as excepted
})
.Verifiable();
var log = mock.Object;
var date = DateTime.Now;
log.LogInformation("message {date}", date); |
The interface for ILogger and the extension methods for LogDebug(), etc. is the problem for me. I had to implement one recently to work with a nuget package and the author had used those extension methods. The ext methods use public class MyLogger : ILogger
{
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
// where is the message sent to the LogDebug extension method?
var flv = state as FormattedLogValues; // doesnt compile due to internal.
// after much guessing and attempts, I found its actually right here, but I dont see anything that would give me that clue.
var message = state.ToString();
...etc |
Lets just make the thing public. I've seen enough evidence that customers would benefit just for testing the extension methods. |
Please don't shoot, a first-time contributor. I'd like to learn how the contribution process looks like. Here's a PR: #85859. |
It's in the exact right shape already? Can you update the top post with the proposed API? |
So, after coming to this thread last week, and seeing all the debate about making what should be a publicly usable class... public, I went and copied the code from An example of how simple maintenance becomes is:
Now I can simply call And if I want different text... I just change the constant and the Unit Test passes. It's also written so a new instance of
Anyway, as with most things the .NET framework should do but doesn't, I went back to 'roll my own copy by duplicating the private code in the framework.' |
@davidfowl , Your suggestion pointed me in the right direction (at least from my perspective in order to achieve the validation behavior I was seeking). I was attempting to validate the originally formatted error message, which contains variable(s) surrounded by curly brackets I used examples other suggested for how to use Moq to verify the logging invocation, combined with a helper function to parse out and validate the key value pair contents: loggerMock.Verify(
x => x.Log(
LogLevel.Error,
It.IsAny<EventId>(),
It.Is<It.IsAnyType>((o, t) => ValidateLoggedState(o, t)),
It.IsAny<Exception?>(),
(Func<It.IsAnyType, Exception?, string>)It.IsAny<object>()
),
Times.Once
); and public bool ValidateLoggedState(object o, Type t)
{
// Cast FormattedLogValues (internal class) to a list of key/value pairs.
IReadOnlyList<KeyValuePair<string, object>> loggedValues = (IReadOnlyList<KeyValuePair<string, object>>)o;
// Validate that a log with the expected message template is present.
bool expectedErrorMsgTemplateExists = loggedValues.Any(kvp => kvp.Key == "{OriginalFormat}" && kvp.Value.ToString() == ErrorMessages.ERRMESSAGEFILEEXISTS);
//Validate that the expected variable was used for filling the template.
//For demonstration purposes since there may not be a point to doing this.
bool formattedErrorMsgExists = loggedValues.Any(kvp => kvp.Key == "runtimeConfigFile");
// Validation result.
return expectedErrorMsgTemplateExists && formattedErrorMsgExists;
} |
With the author of Moq now added a dependency on SponsorLink, which appears to violate a lot of jurisdiction's privacy legislation, we are hunting around for an alterative library for Moq. NSubstitute does not contain an alternative for It.IsAnyType, nor does any other of the major testing libraries. IMHO If published extensions use a public interface method with generic type arguments, it must do so with only public type definitions. Of course implementations can be internal. The use of an internal type makes unit testing of this impossible using (most) mocking libraries. The Logger source generator is also guilty of this. It generates a private struct in the GenericMessages generated code and passes that to the Log method at the TState type argument. @StingyJack We are not trying to test the implementation of ILogger, but verify the invocation. We need the Type of TState type argument to ILogger.Log in order to verify. |
@slaneyrw Can NSubstitute mock generic methods? |
Yes, but as it doesn't have the concept of It.IsAnyType, it needs the type in advance - hence internal and private types cannot be mocked |
What does mocking a generic methods that takes T look like with NSubstitute for ILogger.Log<T> call? |
In the case of the ILogger, you don't set up the call, but verify the
invocation. But the principle is the same
i.e.
mockLogger.Received().Log<FormattedLogValues>( ... )
In Moq, FormattedLogValues generic argument is replaced with "It.IsAnyType"
As you know generic methods type cannot be co/contravariant so we need the
exact type.
There are 2 choices here... either make FormattedLogValues public again, or
explicitly specify the generic type using a known public interface/base of
FormattedLogValues. IReadOnlyList<KeyValuePair<string, object?>> could be
a good candidate.
…On Sat, 12 Aug 2023, 1:15 am David Fowler, ***@***.***> wrote:
Yes, but as it doesn't have the concept of It.IsAnyType, it needs the type
in advance
What does mocking a generic methods that takes T look like with
NSubstitute?
—
Reply to this email directly, view it on GitHub
<#67577 (comment)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/AAUOINAHZRNB32UGT22N6H3XUZEBNANCNFSM5SRSQVEA>
.
You are receiving this because you were mentioned.Message ID:
***@***.***>
|
I am facing a similar issue that was described earlier. I have a method which has a line as follows: _logger.LogError(exception, $"Encountered {exception.GetType().Name}. Unable to verify user with id {user.UserId}"); This has a corresponding unit test with the following assertion: var logger = Substitute.For<ILogger<SyncService>>();
// other Arrange, Act, Assert steps
logger.Received(1).LogError(exception, "Encountered NullReferenceException. Unable to verify user with id 1"); This test was running fine. However, due to some issues we encountered, this log now needs to be converted into a structured log. So now the line in the class looks as follows: _logger.LogError(exception, "Encountered {exceptionType}. Unable to verify user with id {userId}", exception.GetType().Name, user.UserId); But now when I changed the assertion to the following, the test fails: logger.Received(1).LogError(exception, "Encountered {exceptionType}. Unable to verify user with id {userId}", "NullReferenceException", 1); The error message is as follows. I have removed the unwanted stack traces to highlight only the important parts:
I was initially unable to figure out what I am doing incorrectly. From the 2 messages it seems like the correct method is being called with the correct parameters, but the message is still flagged as non-matching. But after some digging I came to realize the flagged message is actually a But I am unable to refer this type directly in my test to be able to appropriately mock it assert to it. |
@arkadeepsaha-ten a lot of the trouble you were facing and some solutions for it are detailed in this thread. There are examples of how to mock ILogger to use for unit tests starting at about this comment. If still having trouble with the matching, try figuring out how the string coming form the logger actually ends. Is it some non-printable or whitespace character following the |
@StingyJack Hi, thanks for the suggestion. I eventually implemented my own instance of ILogger, just for unit testing, but wanted to post my experience here to provide a valid use case for the discussion. As for why the test was failing, it was because I was trying to assert a If anyone is interested, this is my StackOverflow question about the topic along with the resolution: |
Part of the problem that many who come to this thread are facing is that methods like So I think at least one of the solutions to this problem would be to add the signatures those extension methods provide to ILogger (sans the public interface IMyLogger : ILogger
{
void LogError(string? message, params object?[] args);
} Which lets me test the string being sent to the logger in a way that is more recognizable with other things being mocked for testing, and avoids the need to touch [TestMethod]
public void LogErrorTest()
{
var logger = new Mock<IMyLogger>();
var collectedMessages = new List<string>();
logger.Setup(s => s.LogError(It.IsAny<string>(), It.IsAny<object[]>()))
.Callback((string s, object[] parameters) =>
{
collectedMessages.Add(s);
});
logger.Object.LogError(nameof(LogErrorTest));
Assert.AreEqual(1, collectedMessages.Count);
Assert.AreEqual(nameof(LogErrorTest), collectedMessages[0]);
} It is good that the extension methods were made available because many would have probably avoided using ILogger without them. It is probably time to consider promoting them to interface members anyway. For unit testing, I think I would still opt for implementing an ILogger cos its going to be less keystrokes, but even with that I could avoid needing to use FormattedLogValues. |
@StingyJack The problem is trying to mock/substitute/verify the TState can be switched to |
The vast majority, except for a few minor (and generally irrelevant cases) of the logging I do is using If we could mock the But because of |
@perringaiden - You mean this, right? I havent needed to go that deep WRT logging performance. The extension methods have always been good enough. Usually the perf problems with logging systems are towards the middle/end of the logging stack (when log requests arent batched when writing to the repo/sink/store, or the ILogger implementation holds the calling thread for too long, etc). But thanks for pointing this out to me, I wouldn't have gone looking for it otherwise.
@slaneyrw - We just blocked Moq versions 4.20 and later from our package feeds. At worst we would stay on 4.18 forever (which is fine as it does everything we need). At best the community backlash was going to prompt the reverting of the Sponsorlink. which I think is happening. |
I am disappointed this struct is still internal after more than a year and somebody even opened a PR. It is already a hard job to convince some team members and management about the good of unit tests. It makes harder to defend unit tests when a team member stumble on something like this that should have been trivial to mock. It even blocks some developers on this thread from using other tools than Moq. Dotnet seems to take in account the community, multiple peoples raise an issue about this, the negative impacts seems low, pretty please, is it possible to take a moment to review the accessibility of FormattedLogValues? Thank you |
I think that's fair that the impact is pretty low for making this public, even if this is the wrong way to test your logs, this use case is valid. |
Curiosity, the issue is open from April 2022 and there is a tag "triage", is there any plan to review it in 2024? Thanks! |
This is really problematic in tests while the change is really tiny and it seems it does not have negative impact but would help many people |
Another use case is custom attribute formatting for custom ILogger. We were hoping to justs implement a custom ILogger and ILoggerProvider that iterates through the TState object when it is an IEnumerable and handle the object accordingy.
This does not work, however, because the TState can't be modified... I haven't found any other way to implement this using the default ILogger. |
https://github.com/duongphuhiep/ToolsPack.NetCore/tree/master/src/ToolsPack.Logging#mocklogger (While Asserting the log events) I also explained How to display logs message in the Test Output => so you are no longer "blind" when diagnostic a failed test..
using LoggingFormatted = Microsoft.Extensions.Logging.Formatted;
public class DecoratedLogger : ILogger
private ILogger core;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
if (typeof(LoggingFormatted).IsAssignableFrom(typeof(TState)))
{
var currentState = state as LoggingFormatted;
newState = new LoggingFormatted(currentState); // clone the currentState
newState.AddMoreValue(newKey, newValue); //enrich the currentState
core.Log(logLevel, eventId, newState, exception, formatter);
}
else {
core.Log(logLevel, eventId, state, exception, formatter);
}
}
} I can't do it today because the Microsoft.Extensions.Logging.Formatted is not public, so I will have to find other way. |
@davidfowl this is an interesting statement. What would be the right way to test your logs? |
I wasn't aware of this package. Thanks, I'll look into it! |
I think the introduction of the new and excellent If you were a regular reader of the .NET Blog you'd know about it :) https://devblogs.microsoft.com/dotnet/fake-it-til-you-make-it-to-production/ NuGet package: |
@silkfire yes, that's what @davidfowl mentioned. |
Please do not close this discussion. There are other use cases than unit testing for this request. I've had the issue where I wanted to preprocess parameters passed to logger before logging them to console, specifically I wanted to add custom escaping for This would be possible if I could take existing What I had to do is to use reflection hack for this: public static class FormattedLogValuesHelper
{
private static Type _formattedLogValues = Type.GetType("Microsoft.Extensions.Logging.FormattedLogValues, Microsoft.Extensions.Logging.Abstractions") ?? throw new Exception("Cannot find FormattedLogValues type");
public static bool TryMapParameters<TState>(ref TState state, Func<string, object?, object?> mapper)
{
if (typeof(TState) != _formattedLogValues)
{
return false;
}
var values = state as IReadOnlyList<KeyValuePair< string, object?>>;
if (values is null)
{
return false;
}
var list = new object?[values.Count - 1];
bool anyChanged = false;
for (var i = 0; i < values.Count - 1; i++)
{
var value = values[i];
list[i] = mapper(value.Key, value.Value);
if (list[i] != value.Value)
{
anyChanged = true;
}
}
if (!anyChanged)
return false;
var formatString = values[values.Count - 1].Value;
if(Activator.CreateInstance(_formattedLogValues, formatString, list) is TState newState)
{
state = newState;
return true;
}
else
{
return false;
}
}
} With usage: public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
FormattedLogValuesHelper.TryMapParameters(ref state, (name, value) =>
{
if (value is SyntaxNode syntaxNode)
{
// escape every SyntaxNode so that it does not break formatting
return Markup.Escape(syntaxNode.ToString());
}
return value;
});
// use formatter to get the message
AnsiConsole.MarkupLine(formatter(state, exception));
} |
yes I had the same request, I wished to "enrich" or to modify the LoggingFormatted as well using LoggingFormatted = Microsoft.Extensions.Logging.Formatted;
public class DecoratedLogger : ILogger
private ILogger core;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
if (typeof(LoggingFormatted).IsAssignableFrom(typeof(TState)))
{
var currentState = state as LoggingFormatted;
newState = new LoggingFormatted(currentState); // clone the currentState
newState.AddMoreValue(newKey, newValue); //enrich the currentState
core.Log(logLevel, eventId, newState, exception, formatter);
}
else {
core.Log(logLevel, eventId, state, exception, formatter);
}
}
} |
Or you can use the enrichment (or redaction) support added by https://github.com/dotnet/extensions/tree/main/src/Libraries/Microsoft.Extensions.Telemetry#logging-enhancements |
Here's an ILogger wrapper which adds a prefix of your choosing (with templating), if anyone's interested. Thanks @duongphuhiep for providing the secret sauce!
Here's how you use it -
|
https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/FormattedLogValues.cs should be imho public.
There are use cases where I want to log and return or throw same string. Would be handy to do something like:
The text was updated successfully, but these errors were encountered: