Topics

C#•2y ago

❔ .Net Logging - Is this valid?

So i saw this nick chapsas short and I've too passed my message as a string(big error) into the logger. Aka this one: (60 sec video)https://www.youtube.com/shorts/PvQGVmozCdU So I've changed my method to do this:

public static class LoggerExtension
{
    public static void LogWithDetails(
        ILogger logger,
        LogLevel logLevel,
        object[] args,

        string message,
        [CallerFilePath] string filePath = "",
        [CallerMemberName] string functionName = "",
        [CallerLineNumber] int lineNumber = 0)
    {
        var fileName = System.IO.Path.GetFileName(filePath);
        var messageTemplate = "{FileName}:{LineNumber} - {FunctionName}(): " + message;
        var finalArgs = new List<object> { fileName, lineNumber, functionName };
        finalArgs.AddRange(args);
        logger.Log(logLevel, messageTemplate, finalArgs.ToArray());
    }
}

public static class LoggerExtension
{
    public static void LogWithDetails(
        ILogger logger,
        LogLevel logLevel,
        object[] args,

        string message,
        [CallerFilePath] string filePath = "",
        [CallerMemberName] string functionName = "",
        [CallerLineNumber] int lineNumber = 0)
    {
        var fileName = System.IO.Path.GetFileName(filePath);
        var messageTemplate = "{FileName}:{LineNumber} - {FunctionName}(): " + message;
        var finalArgs = new List<object> { fileName, lineNumber, functionName };
        finalArgs.AddRange(args);
        logger.Log(logLevel, messageTemplate, finalArgs.ToArray());
    }
}

Calling it like this:

LoggerExtension.LogWithDetails(_logger, LogLevel.Information, "number of phases to process = {Count}", new object[] { createdLesson.Phases.Count });

LoggerExtension.LogWithDetails(_logger, LogLevel.Information, "number of phases to process = {Count}", new object[] { createdLesson.Phases.Count });

Wanted to make sure this is correct and am not shooting myself in the foot

YouTube

The Biggest Lie About the .NET Logger | .NET Tips 7

The .NET Logging API is lying!

55 Replies

cap5lut•2y ago

well, it can get some improvement, but whats described in the short is implemented. - i would check with ILogger.IsEnabled(logLevel) if it actually makes to further process, if not early return from the method, this way u will avoid some useless overhead (u are creating new instances here after all) - u already know the final args array size, so create that instead of doing the extra "round trip" via the list - i think u forgot a this for the first parameter, so its actually an extension method - args could be a params parameter, so that u do not have to create the array when calling the method urself - i would add additional methods that take 0 to 3 parameters, so that for these methods u avoid another array instantiation

antimatter8189OP•2y ago

taking about smth like this?

public static class LoggerExtension
{
    public static void LogWithDetails(
        this ILogger logger,
        LogLevel logLevel,
        string message,
        params object[] args,
        [CallerFilePath] string filePath = "",
        [CallerMemberName] string functionName = "",
        [CallerLineNumber] int lineNumber = 0)
    {
        if (!logger.IsEnabled(logLevel))
            return;

        var fileName = System.IO.Path.GetFileName(filePath);
        var messageTemplate = "{FileName}:{LineNumber} - {FunctionName}(): " + message;

        var finalArgs = new object[args.Length + 3];
        finalArgs[0] = fileName;
        finalArgs[1] = lineNumber;
        finalArgs[2] = functionName;
        args.CopyTo(finalArgs, 3);

        logger.Log(logLevel, messageTemplate, finalArgs);
    }

    // Overloads for 0-3 parameters
    public static void LogWithDetails(
        this ILogger logger,
        LogLevel logLevel,
        string message,
        [CallerFilePath] string filePath = "",
        [CallerMemberName] string functionName = "",
        [CallerLineNumber] int lineNumber = 0)
    {
        logger.LogWithDetails(logLevel, message, new object[0], filePath, functionName, lineNumber);
    }

    public static void LogWithDetails<T1>(
        this ILogger logger,
        LogLevel logLevel,
        string message,
        T1 arg1,
        [CallerFilePath] string filePath = "",
        [CallerMemberName] string functionName = "",
        [CallerLineNumber] int lineNumber = 0)
    {
        logger.LogWithDetails(logLevel, message, new object[] { arg1 }, filePath, functionName, lineNumber);
    }

  
  
}

public static class LoggerExtension
{
    public static void LogWithDetails(
        this ILogger logger,
        LogLevel logLevel,
        string message,
        params object[] args,
        [CallerFilePath] string filePath = "",
        [CallerMemberName] string functionName = "",
        [CallerLineNumber] int lineNumber = 0)
    {
        if (!logger.IsEnabled(logLevel))
            return;

        var fileName = System.IO.Path.GetFileName(filePath);
        var messageTemplate = "{FileName}:{LineNumber} - {FunctionName}(): " + message;

        var finalArgs = new object[args.Length + 3];
        finalArgs[0] = fileName;
        finalArgs[1] = lineNumber;
        finalArgs[2] = functionName;
        args.CopyTo(finalArgs, 3);

        logger.Log(logLevel, messageTemplate, finalArgs);
    }

    // Overloads for 0-3 parameters
    public static void LogWithDetails(
        this ILogger logger,
        LogLevel logLevel,
        string message,
        [CallerFilePath] string filePath = "",
        [CallerMemberName] string functionName = "",
        [CallerLineNumber] int lineNumber = 0)
    {
        logger.LogWithDetails(logLevel, message, new object[0], filePath, functionName, lineNumber);
    }

    public static void LogWithDetails<T1>(
        this ILogger logger,
        LogLevel logLevel,
        string message,
        T1 arg1,
        [CallerFilePath] string filePath = "",
        [CallerMemberName] string functionName = "",
        [CallerLineNumber] int lineNumber = 0)
    {
        logger.LogWithDetails(logLevel, message, new object[] { arg1 }, filePath, functionName, lineNumber);
    }

  
  
}

cap5lut•2y ago

well, nope, in the overloads u would call the logger.Log(....) directly as well

antimatter8189OP•2y ago

not sure i caught this one too : args could be a params parameter, so that u do not have to create the array when calling the method urself

cap5lut•2y ago

so basically u would need a helper method for var messageTemplate = "{FileName}:{LineNumber} - {FunctionName}(): " + message; to keep it dry

antimatter8189OP•2y ago

can you give me a revised example?

cap5lut•2y ago

private static string GetMessageTemplate(string message) => "{FileName}:{LineNumber} - {FunctionName}(): " + message;
public static void LogWithDetails(
  this ILogger logger,
  LogLevel logLevel,
  string message,
  object arg,
  [CallerFilePath] string filePath = "",
  [CallerMemberName] string functionName = "",
  [CallerLineNumber] int lineNumber = 0)
{
  if (!logger.IsEnabled(logLevel)) return;
  
  filePath = System.IO.Path.GetFilePath(filePath);
  message = GetMessageTemplate(message);

  logger.Log(logLevel, messageTemplate, filePath, functionName, lineNumber, arg);
}

private static string GetMessageTemplate(string message) => "{FileName}:{LineNumber} - {FunctionName}(): " + message;
public static void LogWithDetails(
  this ILogger logger,
  LogLevel logLevel,
  string message,
  object arg,
  [CallerFilePath] string filePath = "",
  [CallerMemberName] string functionName = "",
  [CallerLineNumber] int lineNumber = 0)
{
  if (!logger.IsEnabled(logLevel)) return;
  
  filePath = System.IO.Path.GetFilePath(filePath);
  message = GetMessageTemplate(message);

  logger.Log(logLevel, messageTemplate, filePath, functionName, lineNumber, arg);
}

u also do not need to introduce generic types here, even if u would pass a struct, it would have to be boxed anyway

antimatter8189OP•2y ago

wait how do u actually call this?

object arg,

object arg,

So you would pass in a object like {LastName=LastName,etc..}

cap5lut•2y ago

to the params:

public void Example1(object[] args)
{
  // do stomething
}
public void Example2(params object[] args)
{
  // do the same thing
}

Example1(new object[] { "hello", "world" });
Example2("hello", "world");

public void Example1(object[] args)
{
  // do stomething
}
public void Example2(params object[] args)
{
  // do the same thing
}

Example1(new object[] { "hello", "world" });
Example2("hello", "world");

here exactly the same happens, just that u do not have to type out the new object[] stuff for passing the parameters

antimatter8189OP•2y ago

I see, didnt know about this thats nice

cap5lut•2y ago

ILogger.Log() also has params object[] args for its arguments, thus it will automatically create an array (and i think they also have these optimized versions i was just talking about, but not 100% sure rn) u could also mess with the GetMessageTemplate a bit i guess, because most of the time u will constant strings passed to ur methods, thus u could probably build a ConcurrentDictionary<string, string> around it to cache the template creation

antimatter8189OP•2y ago

Interesting will try to implement so just making sure, This:

        LoggerExtension.LogWithDetails(_logger, LogLevel.Information,
            $"lessonId = {lesson.Id}, number of phases to process = {lesson.Phases.Count}");

        LoggerExtension.LogWithDetails(_logger, LogLevel.Information,
            $"lessonId = {lesson.Id}, number of phases to process = {lesson.Phases.Count}");

Becomes this:

        LoggerExtension.LogWithDetails(
            _logger,
            LogLevel.Information,
            "lessonId = {LessonId}, number of phases to process = {PhaseCount}",
            new { LessonId = lesson.Id, PhaseCount = lesson.Phases.Count }
        );

        LoggerExtension.LogWithDetails(
            _logger,
            LogLevel.Information,
            "lessonId = {LessonId}, number of phases to process = {PhaseCount}",
            new { LessonId = lesson.Id, PhaseCount = lesson.Phases.Count }
        );

Seems decent? based on your code Forget that its not a proper extension method atm, will also adress that later on

cap5lut•2y ago

yep

antimatter8189OP•2y ago

Amazing, thx alot bud 😄

cap5lut•2y ago

wait, quite difficult to say, because of the named templates better try it and see 😂 for {0} and alike it would work for sure

antimatter8189OP•2y ago

Meaning the order can get screwed up? shouldnt happen if i pass parameters in the correct order no? basic stuff What am i missing

cap5lut•2y ago

if u pass them in correct order it should work and then u can also just call it with LoggerExtension.LogWithDetails(_logger, LogLevel.Information, "ur template", lesson.Id, lesson.Phases.Count);

antimatter8189OP•2y ago

but then I gotta do this :

              lesson.Id, lesson.Phases.Count.ToString()

              lesson.Id, lesson.Phases.Count.ToString()

Im guessing the logger itself calls a tostring on the object properties?

cap5lut•2y ago

no u dont have to call ToString()

antimatter8189OP•2y ago

I do, tells me cannot convert from int to string wont compile this the code:

public static class LoggerExtension
{
    private static string GetMessageTemplate(string message) => "{FileName}:{LineNumber} - {FunctionName}(): " + message;
    public static void LogWithDetails(
      this ILogger logger,
      LogLevel logLevel,
      string message,
      object arg,
      [CallerFilePath] string filePath = "",
      [CallerMemberName] string functionName = "",
      [CallerLineNumber] int lineNumber = 0)
    {
        if (!logger.IsEnabled(logLevel)) return;

        filePath = System.IO.Path.GetFileName(filePath);
        message = GetMessageTemplate(message);

        logger.Log(logLevel, message, filePath, functionName, lineNumber, arg);
    }

}

public static class LoggerExtension
{
    private static string GetMessageTemplate(string message) => "{FileName}:{LineNumber} - {FunctionName}(): " + message;
    public static void LogWithDetails(
      this ILogger logger,
      LogLevel logLevel,
      string message,
      object arg,
      [CallerFilePath] string filePath = "",
      [CallerMemberName] string functionName = "",
      [CallerLineNumber] int lineNumber = 0)
    {
        if (!logger.IsEnabled(logLevel)) return;

        filePath = System.IO.Path.GetFileName(filePath);
        message = GetMessageTemplate(message);

        logger.Log(logLevel, message, filePath, functionName, lineNumber, arg);
    }

}

cap5lut•2y ago

it tries to pass it as filePath right now, because u probably do not have the 2 args version nor the params version yet

antimatter8189OP•2y ago

oh right theres that Not sure what youre reffering to

cap5lut•2y ago

the whole thing was talking about basically D: not sure if any of this works then

antimatter8189OP•2y ago

Lol Wait if thats the case then wtf do i do? gotcha, makes sense thanks for pointing that out how would you fix said code to make it work? any workaround? kinda lost

cap5lut•2y ago

its in the extenion methods, not directly in the ILogger interface https://learn.microsoft.com/en-us/dotnet/api/microsoft.extensions.logging.loggerextensions.log?view=dotnet-plat-ext-7.0#microsoft-extensions-logging-loggerextensions-log(microsoft-extensions-logging-ilogger-microsoft-extensions-logging-loglevel-system-string-system-object())

LoggerExtensions.Log Method (Microsoft.Extensions.Logging)

Formats and writes a log message at the specified log level.

antimatter8189OP•2y ago

How does that support my usecase of the caller memebers?

cap5lut•2y ago

we would still have to mess with the stuff a bit with most even i think

antimatter8189OP•2y ago

Yup that what gets me, I cant incorporate that I gotta go for like 30 mins, will be back, if you come up with smth please write i will check it, very important to me to get this done lol thx for now mate!

cap5lut•2y ago

yeah im still looking into it so, not even something like log.Log(LogLevel.Information, "example {TestId}", new { TestId = 16 }); works. it would result in something like

info: Program[0]
      example { TestId = 16 }

info: Program[0]
      example { TestId = 16 }

where logger.Log(LogLevel.Information, "example {TestId} {AnotherTest}", new { TestId = 16, AnotherTest = "test" }); would be totally broken and result in a System.AggregateException. thats because it resolves to the method i linked earlier. but passing the values as parameters each, does work, but u have to care about the order then and it completely ignores whats inside the {} so logger.Log(LogLevel.Information, "example {0} {1} {0}", 16, "test"); would break again. u would have to call logger.Log(LogLevel.Information, "example {0} {1} {0}", 16, "test", 16); u also can not use the params variant because it always has to be the last parameter, thus u would not be able to use the [Caller...] attributes thus u would have to use something logger.LogWithDetails(LogLevel.Information, "example {} {} {}", new object[] { "hello", "test", 16 }); for calls for which u did not write a method with explicit argument count so if u implement this

cap5lut•2y ago

message.txt

cap5lut•2y ago

u r still screwed, because it resolves to the wrong methods and thus has wrong parameter count for formatting so the only real way is to resolve it from the System.Environment.StackTrace property. which will be quite annoying

antimatter8189OP•2y ago

Omfg lol

cap5lut•2y ago

(note, that the array variant does work)

antimatter8189OP•2y ago

So basically no solution for this? i gotta drop the members?

cap5lut•2y ago

actually, u can use the System.Diagnostics.StackTrace class to retrieve the info, unlike System.Environment.StackTrace thats a normal class with properties. so that should be easier then u can drop the [Caller...] annotated parameters and it should work. additionally u would then again be able to use the params so something like this:

    public static void LogWithDetails(this ILogger logger, LogLevel logLevel, string message, params object?[] args)
    {
        if (!logger.IsEnabled(logLevel)) return;

        var frame = new StackTrace().GetFrame(1);
        var finalArgs = new object?[args.Length + 3];
        finalArgs[0] = frame?.GetFileName();
        finalArgs[1] = frame?.GetFileLineNumber();
        finalArgs[2] = frame?.GetMethod()?.Name;
        args.CopyTo(finalArgs, 3);
        logger.Log(logLevel, GetMessageTemplate(message), finalArgs);
    }

    public static void LogWithDetails(this ILogger logger, LogLevel logLevel, string message, params object?[] args)
    {
        if (!logger.IsEnabled(logLevel)) return;

        var frame = new StackTrace().GetFrame(1);
        var finalArgs = new object?[args.Length + 3];
        finalArgs[0] = frame?.GetFileName();
        finalArgs[1] = frame?.GetFileLineNumber();
        finalArgs[2] = frame?.GetMethod()?.Name;
        args.CopyTo(finalArgs, 3);
        logger.Log(logLevel, GetMessageTemplate(message), finalArgs);
    }

but note that it comes from debug symbols, so my simple test program even spit out null and 0 for file name and line number

antimatter8189OP•2y ago

wouldnt it perhaps be smarter, to just pass those parameters from a single fuction and add them to the array? why do i need a trace

cap5lut•2y ago

ffs i simply forgot to pass true, so var frame = new StackTrace(true).GetFrame(1); and at least in debug mode u get some stuff that should work as well if i understood it correctly

antimatter8189OP•2y ago

Actually no it wouldnt if i create this method:

    public static CallerDetails GetCallingMemberMetaData(

            [CallerFilePath] string filePath = "",
            [CallerMemberName] string functionName = "",
            [CallerLineNumber] int lineNumber = 0)
    {
        return new CallerDetails(filePath,functionName,lineNumber) ;
    }

    public static CallerDetails GetCallingMemberMetaData(

            [CallerFilePath] string filePath = "",
            [CallerMemberName] string functionName = "",
            [CallerLineNumber] int lineNumber = 0)
    {
        return new CallerDetails(filePath,functionName,lineNumber) ;
    }

and call it from the logwithDetails, then the caller will be from the same file etc not good at all

cap5lut•2y ago

@AntiMatter this works:

public readonly record struct CallSite(string? FilePath, int LineNumber, string? MethodName);

public static class LoggerExtensions
{
    private static string GetMessageTemplate(string message) => "{}:{} - {}():" + message;

    public static CallSite GetCallSite(this ILogger logger, [CallerFilePath] string? filePath = null, [CallerLineNumber] int lineNumber = 0, [CallerMemberName] string? methodName = null)
    {
        return new CallSite(filePath, lineNumber, methodName);
    }

    public static void Log(this ILogger logger, LogLevel logLevel, CallSite callSite, string message, params object?[] args)
    {
        if (!logger.IsEnabled(logLevel)) return;

        var finalArgs = new object?[args.Length + 3];
        finalArgs[0] = Path.GetFileName(callSite.FilePath);
        finalArgs[1] = callSite.LineNumber;
        finalArgs[2] = callSite.MethodName;
        args.CopyTo(finalArgs, 3);
        logger.Log(logLevel, GetMessageTemplate(message), finalArgs);
    }
}

public readonly record struct CallSite(string? FilePath, int LineNumber, string? MethodName);

public static class LoggerExtensions
{
    private static string GetMessageTemplate(string message) => "{}:{} - {}():" + message;

    public static CallSite GetCallSite(this ILogger logger, [CallerFilePath] string? filePath = null, [CallerLineNumber] int lineNumber = 0, [CallerMemberName] string? methodName = null)
    {
        return new CallSite(filePath, lineNumber, methodName);
    }

    public static void Log(this ILogger logger, LogLevel logLevel, CallSite callSite, string message, params object?[] args)
    {
        if (!logger.IsEnabled(logLevel)) return;

        var finalArgs = new object?[args.Length + 3];
        finalArgs[0] = Path.GetFileName(callSite.FilePath);
        finalArgs[1] = callSite.LineNumber;
        finalArgs[2] = callSite.MethodName;
        args.CopyTo(finalArgs, 3);
        logger.Log(logLevel, GetMessageTemplate(message), finalArgs);
    }
}

logger.Log(LogLevel.Information, logger.GetCallSite(), "example {} {} {} {}", "hello", "test", 16, 17); prints

info: Program[0]
      Program.cs:12 - <Main>$():example hello test 16 17

info: Program[0]
      Program.cs:12 - <Main>$():example hello test 16 17

u could probably even make it a ref struct so it can not get boxed (tho then u cant use it in an async method anymore) (and u dont even have to call it LogWithDetails, as its clear from passing the CallSite parameter, which method it has to call)

antimatter8189OP•2y ago

does GetMessageTemplate return compile const?

cap5lut•2y ago

probably not

antimatter8189OP•2y ago

so thats no good =[

cap5lut•2y ago

probably depends on message but at this point the compiler cant know if its compile const

antimatter8189OP•2y ago

will try to inject it into the log config/creation

cap5lut•2y ago

well, i think with a ConditionalWeakTable<string, string> (not the ConcurrectDictionary<string, string>) u can at least avoiding creating multiple instances by using thatTable.GetValue(message, static m => "{}:{} - {}():" + message); i guess. and iirc the lookup is also O(1), so pretty fast, and it automatically drops it if message will be GCed

antimatter8189OP•2y ago

will check it out boss if any news will update 😄 thx alot!

cap5lut•2y ago

sure, but im hitting the sack for tonight, 10.45pm and i didnt sleep last night 😂

antimatter8189OP•2y ago

same here lol mind blown over these logs time to get off

cap5lut•2y ago

thats what i came up with in the end: https://gist.github.com/cap5lut/593468756bda861f4189217ec1dfd371 i removed the coupling from the call site factory method to the logger, so now its just CallSite.Get(), so u could also use it somehwere else. it would also probably be better to wrap the Path.GetFileName(callSite.FilePath); in its own method to keep it DRY in case u want to adjust it later somehow i would also probably add the methods where u dont have to pass the loglevel, like ILogger.LogError(...) and alike maybe even just throw it all in a source generator cuz its mainly copy and paste. ofc the namespaces should also be adjusted, imo CallSite shouldnt even be in a logging namespace, as it has only indireclty to do with it.

Tvde1•2y ago

Make your log messages unique :) Then you know where it came from

cap5lut•2y ago

yeah, where to look should be actually clear by the default provided stuff, eg, the type the logger is for and ofc the distinctive message itself but was sorta interesting to check how to extend the api surface for that ;p

Accord•2y ago

Was this issue resolved? If so, run /close - otherwise I will mark this as stale and this post will be archived until there is new activity.

antimatter8189OP•2y ago

oh just saw it now, will check it out! I was sure it a bust, did you actually check about the memory allocation stuff by any chance?

cap5lut•2y ago

nope

Accord•2y ago

Was this issue resolved? If so, run /close - otherwise I will mark this as stale and this post will be archived until there is new activity.

We are a programming server aimed at coders discussing everything related to C# (CSharp) and .NET.

54KMembers

View on Discord

Did you find this page helpful?