Serilog: Add Support for Interpolated String

[Pvlerick]

When using C# 6.0, it is currently not possible to use interpolated strings to log.

Taking the example from Serilog's home page

var position = new { Latitude = 25, Longitude = 134 };
var elapsedMs = 34;

log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

At the moment, there is no way to use the interpolated string and use Serilog's serializer.

log.Information($"Processed {position} in {elapsedMs:000} ms.");

It would be nice to be able to use interpolated string while at the same time take advantage of Serilog's serializer, using something like:

log.Information($"Processed @{position} in @{elapsedMs:000} ms.");

This is doable using methods that expect a FormattableString, however if there are overloads also taking a string, the string will be preferred by the compiler. One way to make it work is to have all the string overloads being extension methods instead of instance methods.

I wrote a gist to demonstrate: https://gist.github.com/Pvlerick/f4d0876b82f85ef369d0

The implementation is quick and dirty but only serves to prove that it's doable. There might also be ways to implement that that I didn't think of, of course :smile:

Also, an potential issue is that this relies on the compiler's behaviour, which probably won't be in the specifications (I wrote an blog post on this with more details). However I think it is possible to make the implementation robust enough to work in all cases.

[khellang]

I'm not sure how support for FormattableString would help much here. At least not until https://github.com/dotnet/roslyn/issues/142 is resolved.

What would you do for scenarios like log.Information($"Processed {Path.Combine(folderPath, fileName)} in {elapsedMs:000} ms.");?

Also, for reference; C# 6 string interpolation and Serilog

[IanYates]

@Pvlerick - neat blog post! I too had thought about this in the past and, even with @nblumhardt 's blog post in mind, it's worth exploring.

@khellang is right about the given scenario. Part of me thinks that "perfect is the enemy of the good" and the referenced Roslyn issue will eventually provide a solution. In the meantime logging with dummy placeholders wouldn't be the end of the world. The other part of me worries that something is built and then breaks in future. Food for thought :fork_and_knife:

[Pvlerick]

@IanYates thanks. I agree that this is kind of a can of worms and as you rightly pointed it might lead to something fragile that could break in the future.

I'll keep investigating and see if there is a way to make this work nicely with regards to @khellang's and @nblumhardt's points and we'll see.

[pmunin]

easy:
log.Information_($"Processed {new {Position = position}} in {new {Elapsed = elapsed}:000} ms.")

I had to implement it as extension with "_"-suffix, because otherwise roslyn invokes ILogger.Information(string) instead:

    public static class LoggerExtensions
    {
        public class FormattableLogPropValue : IFormattable
        {
            public FormattableLogPropValue(string name, object value)
            {
                this.Name = name;
                this.Value = value;
            }

            public string Name { get; }
            public object Value { get; }

            public bool IsObject() {
                var type = Value?.GetType();
                var res = Type.GetTypeCode(type)==TypeCode.Object;
                return res;
            }

            public string ToString(string format, IFormatProvider formatProvider)
            {
                var prefix = IsObject() ? "@" : string.Empty;
                if (format?.Length > 0) format = ":" + format;
                return $"{{{prefix}{Name}{format}}}";
            }

            public override string ToString()
            {
                return this.ToString(null, null);
            }
        }

        public static void Information_(this ILogger logger, FormattableString str)
        {
            var loggables = str.GetArguments().Select(arg=>GetPropValueFromArgument(logger, arg)??arg).ToArray();

            var messageTemplate = string.Format(str.Format, args: loggables.Select(arg => GetPropValueFromArgument(logger,arg)??arg).ToArray());

            var propertyValues = loggables.OfType<FormattableLogPropValue>().Select(pv=>pv.Value).ToArray();
            logger.Information(messageTemplate, propertyValues: propertyValues);
        }


        static FormattableLogPropValue GetPropValueFromArgument(ILogger logger, object arg)
        {
            var argType = arg.GetType();
            if (!argType.Name.StartsWith("<>f__AnonymousType")) return null;
            var props = argType.GetProperties();
            if (props.Length != 1) throw new ArgumentException("Parameter should only have single property");
            var prop = props.First();
            return new FormattableLogPropValue(prop.Name, prop.GetValue(arg));
        }
    }

Does anyone want to submit a PR?

[Drizin]

I've just published a library (with extensions to Serilog, NLog, and Microsoft ILogger) that allows writing log messages using interpolated strings and yet defining the property names through different syntaxes.
Would love to hear some feedback.
https://github.com/Drizin/InterpolatedLogging