How to use params keyword along with caller Information in C#?

Question

I am trying to combine the C# 5.0 Caller Information along with the C# params keyword. The intention is to create a wrapper for a logging framework, and we want the logger to format the text like String.Format. In previous versions, the method looked like this:

void Log(
   string message,
   params object[] messageArgs = null);

And we call it like this:

log.Log("{0}: I canna do it cap'n, the engines can't handle warp {1}!", 
        "Scotty", warpFactor);

Now, we want to capture caller information and log that as well. So the signature becomes:

void Log(
    string message,
    params object[] messageArgs,
    [CallerMemberName] string sourceMemberName = null);

That doesn't compile because the params must be last parameter. So I try this:

void Log(
    string message,
    [CallerMemberName] string sourceMemberName = null,
    params object[] messageArgs);

Is there a way to call that without either providing sourceMembername, or assigning the messageArgs argument explicitly as a named parameter? Doing so defeats the purpose of the params keyword:

// params is defeated:
log.Log("message", 
        messageArgs: new object[] { "Scotty", warpFactor });
// CallerMemberName is defeated:
log.Log("message", null,
        "Scotty", warpFactor);

Is there a way to do this? It seems like the "hacky" way the caller information is passed precludes using the params keyword. It would be awesome if the C# compiler recognized that the caller member information parameters aren't really parameters at all. I can see no need to ever pass them explicitly.

My backup will be to skip the params keyword, and the caller will have to use the long signature in that last example.

Aguish

Cant you do it with a plain old overload that does not include the sourceMemberName parameter? – Onaonager

@Louis: The point is that they want the methods to include that parameter. It gets automatically populated by the compiler, because of the [CallerMemberName] attribute. – Stick

I asked this question previously and received a few helpful suggestions. My answer to that question includes the approach I wound up taking to get around this limitation. – Tragedienne

Dan: I thought I looked through all questions tagged callermembername. Sorry I missed that one. – Aguish

Answer 1

I don't think that it can be done in exactly the way you want to do it. However, I could think of a few viable workarounds which would probably give you almost the same benefits.

1. Use an intermediate method call to capture the caller member name. The first method call returns a delegate which can in turn be called to provide the additional parameters. This looks weird, but it should work:

   log.Log()("{0}: I canna do it cap'n, the engines can't handle warp {1}!", 
   "Scotty", warpFactor);
   

   One disadvantage here is that it's possible to call log.Log("something"), expecting that your message will be logged, and nothing will happen. If you use Resharper, you can mitigate this by adding a [Pure] attribute to the Log() method so you get a warning if someone doesn't do anything with the resulting object. You could also tweak this approach slightly, saying:

   var log = logFactory.GetLog(); // <--injects method name.
   log("{0}: I canna do it cap'n, the engines can't handle warp {1}!", 
       "Scotty", warpFactor);
   

2. Produce your log messages with lambdas, and let string.Format take care of the params array:

   log.Log(() => string.Format("{0}: I canna do it cap'n, the engines can't handle warp {1}!", 
       "Scotty", warpFactor));
   

   This is the approach that I typically use, and it has some side advantages:

   1. Your log method can catch exceptions produced while producing the debug string, so instead of breaking your system you just get an error that says: "Failed to produce log message: [exception details]".

   2. Sometimes the object you pass to your format string might incur additional cost, which you'd only want to incur when you need it:

      log.Info(() => string.Format("{0}: I canna do it cap'n, the engines can't handle warp {1}!", 
          _db.GetCurrentUsername(), warpFactor));
      

      You'd prefer not to have the above code do a database trip if info-level logging is not turned on.

   As a side note, I find myself using string.Format often enough that I've created a helper method to shorten the syntax slightly:

   log.Log(() => "{0}: I canna do it cap'n, the engines can't handle warp {1}!" 
       .With("Scotty", warpFactor));
   

Stick

The first options looks cool. You'd need to create a custom delegate with the params attribute for it to work, though. – Stylet

Wow, those are some really innovative ideas. Lemme play around with that. I won't be able to use #2 verbatim because we actually pass a lambda that points to the resource string for message. I just removed that detail from the question. So our calls are actually log.Log(() => Resources.EngineWarpError, ...) but I think the technique could still be used. – Aguish

@MobyDisk: Thanks. I also added some information to the answer that you may find useful. – Stick

I just want to mention the obvious alternative here, that you can always do a string.Format() or your .With() extension without the lambdas. Delegates do add some overhead, so I usually save it for arguments that are expensive to create. – Devise

@AndreasLarsen: True, but the overhead for delegates is miniscule. If the log level is high so the message won't be logged, the delegate will cause far less overhead than building the string. If the message is logged, the cost of building the string plus I/O will dwarf the delegate's overhead. Besides that, you can catch exceptions in the delegate. I once had my logging methods accept strings in case I was logging a constant string that needed no building, but I found it was too easy to forget to use the lambda version for expensive strings when the signature allowed just a string. – Stick

Answer 2

To go along with StriplingWarrior suggestion instead of a delegate you could do it with a fluent syntax.

public static class Logger
{
    public static LogFluent Log([CallerMemberName] string sourceMemberName = null)
    {
        return new LogFluent(sourceMemberName);
    }
}

public class LogFluent
{
    private string _callerMemeberName;

    public LogFluent(string callerMamberName)
    {
        _callerMemeberName = callerMamberName;
    }

    public void Message(string message, params object[] messageArgs)
    {

    }
}

Then call it like

Logger.Log().Message("{0}: I canna do it cap'n, the engines can't handle warp {1}!", "Scotty", 10);

Logger doesn't have to be static but it was a simple way to demonstrate the concept

Calpac

I was just playing around with that very thing... it's more verbose than Stripling's solution, but clearer to understand. – Aguish

Answer 3

Well, let me mention one option; you can use reflection to get exact same name, as CallMemberName. This will be definitely slower. Assuming you don't log every millisecond, it will be enough to handle the pressure, I believe.

var stackTrace = new StackTrace(); var methodName = stackTrace.GetFrame(1).GetMethod().Name;

Gilly

This is actually how our old logger does it, I was just hoping for the speed benefit. I may consider this option since it is syntactically the cleanest. – Aguish

Answer 4

I like following Jim Christophers (@beefarino) pluralsight course to setup my own logging projects. For that I clone the ILog interface as ILogger, I implement that - lets say in a class called LoggerAdapter - and then I use Jim Christophers LogManager to have a GetLogger(Type type)-Method that returns a wrapped log4net-logger 'LoggerAdapter':

namespace CommonLogging
{
    public class LogManager : ILogManager
    {
        private static readonly ILogManager _logManager;

        static LogManager()
        {
            log4net.Config.XmlConfigurator.Configure(new FileInfo("log4net.config"));
            _logManager = new LogManager();
        }

        public static ILogger GetLogger<T>()
        {
            return _logManager.GetLogger(typeof(T));
        }

        public ILogger GetLogger(Type type)
        {
            var logger = log4net.LogManager.GetLogger(type);
            return new LoggerAdapter(logger);
        }
    }
}

The next step is to create a generic extension like this, setting the caller-information into a ThreadContext.Property:

public static class GenericLoggingExtensions
{
    public static ILogger Log<TClass>(this TClass klass, [CallerFilePath] string file = "", [CallerMemberName] string member = "", [CallerLineNumber] int line = 0)
        where TClass : class
    {
        ThreadContext.Properties["caller"] = $"[{file}:{line}({member})]";
        return LogManager.GetLogger<TClass>();
    }
}

Having that in place I can always call up a logger before writing an actual method by just calling:

this.Log().ErrorFormat("message {0} {1} {2} {3} {4}", "a", "b", "c", "d", "e");

and if you have the conversionPattern of your PatternLayout configured to use the property:

<layout type="log4net.Layout.PatternLayout">
  <conversionPattern value="%utcdate [%thread] %-5level %logger - %message - %property{caller}%newline%exception" />
</layout>

you will always have a proper output with callerinformation of the first .Log()-call:

2017-03-01 23:52:06,388 [7] ERROR XPerimentsTest.CommonLoggingTests.CommonLoggingTests - message a b c d e - [C:\git\mine\experiments\XPerimentsTest\CommonLoggingTests\CommonLoggingTests.cs:71(Test_Debug_Overrides)]

Salver