parameter not serializing after upgrade to 4.0

[zachrybaker]

Description Parameter is not serializing after upgrade to 4.0

Reproduction Giving the following code

string shadow_requestSeparator  = "";
public static ShadowLogInfo LogRequest(string programName, dynamic parameters = null)
{
    ShadowLogInfo shadowLogInfo = new ShadowLogInfo(programName); // POCO

    var event_type = "shadow";

    Log.Information("{@shadow_requestSeparator}{\n\t\"Request\": {\n\t\t\"ProgramInfo\": {@shadowLogInfo},\n\t\t\"CallData\":{@parameters},\n\t\t\"EventType\":\"{@event_type}\"\n\t}",  
        shadow_requestSeparator, shadowLogInfo, parameters, event_type);

    if (shadow_requestSeparator == "")
        shadow_requestSeparator = ",";

    return shadowLogInfo;
}

the output is failing to handle the @shadowLogInfo parameter

2024-09-09 15:22:05.514 -05:00
 [INF] {
    "Request": {
        "ProgramInfo": {@shadowLogInfo},
        "CallData":{"Id":"8e91b973-6473-40f3-b3b2-50b46cba4e3f","Program":"ZNNPCCS","StartTimestamp":20424887337546,"EndTimestamp":null,"DurationMs":null,"StartDateString":"9/9/2024 3:22:05 PM","ShadowLibrary":null,"CanopyClass":null,"IPCRequestClass":null,"IPCResponseClass":null,"$type":"ShadowLogInfo"},
        "EventType":"{ callId = 3246d8b2-7234-426d-9b4a-103419494eb0, operUin = 701005790, racfId = K156AZB }"
    }

Expected behavior Expect to see: 2024-09-09 15:22:05.514 -05:00 { "Request": { "ProgramInfo": {"Id":"8e91b973-6473-40f3-b3b2-50b46cba4e3f","Program":"ZNNPCCS","StartTimestamp":20424887337546,"EndTimestamp":null,"DurationMs":null,"StartDateString":"9/9/2024 3:22:05 PM","ShadowLibrary":null,"CanopyClass":null,"IPCRequestClass":null,"IPCResponseClass":null,"$type":"ShadowLogInfo"}, "CallData": { "callId": "3246d8b2-7234-426d-9b4a-103419494eb0", "operUin": "701005790", "racfId": "K156AZB" } "EventType": "shadow" } }

Relevant package, tooling and runtime versions 4.0.1 on Windows

Additional context Note that the off-by-one bug starts with the 2nd parameter, not the first, and that the rest of the parameters are off accordingly.

[nblumhardt]

Hi @zachrybaker,

In .NET format strings and message templates, standalone { and } need to be escaped by doubling, {{ and }}:

Log.Information("{@shadow_requestSeparator}{{\n\t\"Request\": {{n\t\t\"ProgramInfo\": {@shadowLogInfo},\n\t\t\"CallData\":{@parameters},\n\t\t\"EventType\":\"{@event_type}\"\n\t}}",  

[zachrybaker]

Shouldn’t that have been an issue prior to 4.0?

[nblumhardt]

Behavior in the presence of invalid templates is undefined; v4 included quite a few changes and improvements to the message template parser, it's likely that behavior changed here.

Tangentially - for the kind of output you're creating, you might find https://nblumhardt.com/2021/06/customize-serilog-json-output/ more reliable; HTH!

[zachrybaker]

Thank you, I wasn't really very aware of the unique message parsing for Serilog, and this output worked for 3 years.... Also, thanks for the pointer to an alternative.

[zachrybaker]

For anyone else that comes across this issue, they may find the Rosalyn Analyzer for Serilog message templates helpful.

https://github.com/Suchiman/SerilogAnalyzer?tab=readme-ov-file

Thanks @nblumhardt