Numeric format specifier not respected

[omfgicbf]

Does this issue relate to a new feature or an existing bug?

• Bug
• New Feature

What version of Serilog is affected? Please list the related NuGet package.
Serilog 2.8.0

What is the target framework and operating system? See target frameworks & net standard matrix.

• netCore 2.0
• netCore 1.0
• 4.7
• 4.6.x
• 4.5.x

Please describe the current behavior?
The hex numeric format specifier does not work unless supplied using standard C# string interpolation. This means I cannot use structured logging if I wish to retain the formatted string in the standard log output.

int status = 16;

log.Error($"Status [0x{status:X8}]"); // "Status [0x00000010]"
log.Error("Status [0x{status:X8}]", status); // "Status [0x16]"
log.Error("Status [0x{0:X8}]", status); // "Status [0x16]"

Please describe the expected behavior?

int status = 16;

log.Error($"Status [0x{status:X8}]"); // "Status [0x00000010]"
log.Error("Status [0x{status:X8}]", status); // "Status [0x00000010]"
log.Error("Status [0x{0:X8}]", status); // "Status [0x00000010]"

Apologies in advance if this is not how it's meant to work. I tried looking for documentation addressing this specific case and couldn't (easily) find it, however, https://github.com/serilog/serilog/wiki/Writing-Log-Events states:

Message templates are a superset of standard .NET format strings, so any format string acceptable to string.Format() will also be correctly processed by Serilog

[nblumhardt]

Thanks for the note!

This is indeed a bug; I think it might have evaded us because it does not affect the console sink; I get the correct output in Serilog.Sinks.Console, but in Serilog.Sinks.File I see:

2019-06-19 00:56:24.724 +10:00 [ERR] Status [0x16]

The code that should be responsible for passing through the correct numeric format is: https://github.com/serilog/serilog/blob/dev/src/Serilog/Events/ScalarValue.cs#L90 - needs some breakpoint debugging to work out what's gone wrong.

[san127127]

Here is what I found:

File sink internally use MessageTemplateTextFormatter.
When I called

using (var log = new LoggerConfiguration()
    .WriteTo.File(@"123.txt")
    .CreateLogger())
    {
        log.Information("x = {x:X8}", 16);
    }

Then, on MessageTemplateTextFormatter.cs line 90-93

if (pt.PropertyName == OutputProperties.MessagePropertyName)
{
    MessageTemplateRenderer.Render(logEvent.MessageTemplate, logEvent.Properties, writer, pt.Format, _formatProvider);
}

logEvent.Template is "{x = {x:X8}}" but pt.Format is "lj" (pt is PropertyToken "{{Message:lj}}")

Since the "format" argument of MessageTemplateRenderer.Render(), pt.Format, contains a "j", "x" is rendered using JsonValueFormatter in MessageTemplateRenderer.RenderValue().

As a result, x is rendered as "16"

[nblumhardt]

Thanks for looking into this; you've reminded me that we've been looking at some related behavior lately (CC @tsimbalar). It's going to require some thought, at least around how to avoid the confusion/footgun.

[san127127]

So I guess we are not going to fix this at this moment?

[nblumhardt]

@csleead I have #1325 in the works