Support {Properties} in output templates #944

Pliner · 2017-03-06T19:41:00Z

Hi guys!

Here is a small addition to the Serilog 😉

nblumhardt · 2017-03-06T22:38:31Z

Thanks for the PR, @Pliner!

It doesn't look like this implementation excludes the properties accounted for by the message template (see the example in #825).

Pliner · 2017-03-08T18:36:43Z

@nblumhardt Thank you for the feedback. Without any doubts I missed that requirement 😞

After brief investigation I found two ways to fix it:

Check MessageTemplate.NamedProperties
Filter MessageTemplate.Tokens to PropertyToken[] and check.

Could you tell me what way you prefer or maybe you can advice me another one? Thanks...

Pliner · 2017-03-08T18:52:34Z

@nblumhardt Anyway, I pushed fix with inspecting MessageTemplate.NamedProperties.

nblumhardt · 2017-03-08T22:49:30Z

src/Serilog/Formatting/Display/LogEventPropertiesValue.cs

+            var delim = "";
+            foreach (var kvp in _properties)
+            {
+                if (_template.NamedProperties.Any(x => x.PropertyName == kvp.Key))


Since NamedProperties is an array, this can use indexer-based access and avoid allocating a LINQ enumerator. (Keeping an eye on allocations, as they build up.)

nblumhardt · 2017-03-08T22:51:16Z

Looking good! Just the minor comment.

@serilog/reviewers-core any thoughts on this one?

adamchester

I like it

nblumhardt · 2017-03-09T02:16:26Z

Cool! :-) Me too. I think we should just make the LINQ change then hit the button.

Pliner · 2017-03-09T11:46:27Z

@nblumhardt I hope I fixed your comment 😉

nblumhardt · 2017-03-10T05:10:53Z

src/Serilog/Formatting/Display/LogEventPropertiesValue.cs

+
+        static bool TemplateContainsPropertyName(MessageTemplate template, string propertyName)
+        {
+            foreach (var namedProperty in template.NamedProperties)


@Pliner I actually had the ol' for(var i = ... in mind here.

nblumhardt · 2017-03-10T05:15:19Z

Added a clarification. Thanks @Pliner!

Just stepping back for a second, there's one scenario where this might not be enough to achieve what we want.

I.e. in Serilog.Extensions.Logging.File we use the output template:

{Timestamp:o} {RequestId,13} [{Level:u3}] {Message} ({EventId:x8}){NewLine}{Exception}

To take advantage of this change, we'd want something resembling:

{Timestamp:o} {RequestId,13} [{Level:u3}] {Message} ({EventId:x8}) {Properties}{NewLine}{Exception}

Although we've got RequestId and EventId going out on every line, they'll still be repeated in the {Properties} block.

Maybe not a show-stopper, but possibly worth a second thought?

Pliner · 2017-03-14T06:33:00Z

@nblumhardt To be honest, log4net approach is ok for me: if %properties% is used in patternlayout, all properties from all contexts will be captured with any exclusions.

nblumhardt · 2017-03-14T23:20:32Z

Thanks for the follow-up Yuri. I guess the difference here is that for log4net, the %properties% layout will not duplicate data that's in the log message, because log4net doesn't capture the arguments to the message format string the way Serilog does. With Serilog, there will be 100% duplication of these if we don't exclude them.

Noctis- · 2017-03-20T10:20:33Z

Hey guys, what's the reasoning behind preferring the for loop to the foreach one ?

nblumhardt · 2017-04-02T08:28:19Z

@Noctis- microbenchmarks :-) ... less allocation.

nblumhardt · 2017-04-02T08:29:16Z

@serilog/reviewers-core any thoughts/opinions on #944 (comment) ?

adamchester · 2017-04-02T08:45:27Z

I think {Properties} should not include those properties already rendered in the message template.

adamchester · 2017-04-02T08:48:19Z

Another quick note that provides more evidence... in Logary we also implemented it by ignoring the fields already in the template.

merbla · 2017-04-02T21:35:45Z

Agreed, we should not duplicate.

Pliner · 2017-04-03T07:30:19Z

@nblumhardt @adamchester @merbla
Thank you for the feedback 😉

Will make another commit today or tomorow.

nblumhardt · 2017-04-03T09:49:47Z

Thank you @Pliner :-) 👍

Pliner · 2017-04-04T18:54:15Z

@nblumhardt I'm not sure about my approach, but now I haven't any ideas how to do it differently 😢

nblumhardt · 2017-04-04T20:53:46Z

Great! I think it's about as good as we are likely to get, here, without deeper changes (which we could still consider in the future).

?

johnduhart · 2017-04-04T21:07:18Z

src/Serilog/Formatting/Display/OutputProperties.cs

@@ -72,7 +72,7 @@ public static class OutputProperties
            result[TimestampPropertyName] = new ScalarValue(logEvent.Timestamp);
            result[LevelPropertyName] = new LogEventLevelValue(logEvent.Level);
            result[NewLinePropertyName] = new LiteralStringValue(Environment.NewLine);
-            result[PropertiesPropertyName] = new LogEventPropertiesValue(logEvent.MessageTemplate, logEvent.Properties);
+            result[PropertiesPropertyName] = new LogEventPropertiesValue(logEvent.MessageTemplate, logEvent.Properties, result);


I would just add a comment before this line to remind future explorers to make sure this property always comes last so it picks up all the existing properties.

Pliner · 2017-04-05T08:27:26Z

@nblumhardt Sorry, but I have to rewrite implementation, because agait it doesn't do everything right.

I should not use output properties, but use output message template instead.

drastically changed

Pliner · 2017-04-05T10:32:39Z

@adamchester Unfortunatly yes, because previous implementation is simply not working 😞

nblumhardt · 2017-04-05T10:38:45Z

src/Serilog/Formatting/Display/OutputProperties.cs

        /// <returns>A dictionary with properties representing the log event.</returns>
-        public static IReadOnlyDictionary<string, LogEventPropertyValue> GetOutputProperties(LogEvent logEvent)
+        public static IReadOnlyDictionary<string, LogEventPropertyValue> GetOutputProperties(LogEvent logEvent, MessageTemplate outputTemplate)


Unfortunately, this will break the literate console sink binary:

https://github.com/serilog/serilog-sinks-literate/blob/dev/src/Serilog.Sinks.Literate/Sinks/Literate/LiterateConsoleSink.cs#L88

One obvious option would be to:

Keep this overload

Add back the one without the additional parameter, but make it forward calls to the full version (we could pass MessageTemplate.Empty as outputTemplate, so that the arguments could still be null-checked)

Mark the old overload [Obsolete("Pass the full output template using the other overload.")]

An alternative, which might be worth considering, is to add the new overload as internal, mark the old one obsolete, and stop offering a public GetOutputProperties() at some time in the future. With the literate console being the only consumer, it may be defensible to simply duplicate the code there.

I like the latter alternative because it'd allow us to re-think how the MessageTemplateTextFormatter works in the future - hopefully to improve on the O(N) scans of the message templates - without then needing to break further public API surface.

Any thoughts?

nblumhardt · 2017-04-05T10:40:30Z

@Pliner good spotting - thanks for the thorough check :-)

Pliner · 2017-04-05T17:17:36Z

@nblumhardt I made an obvious changes for backward compatibility as you mentioned before.

nblumhardt · 2017-04-05T22:18:14Z

🎉 thanks for the great contribution, Yuri!

adamchester · 2017-04-05T22:26:16Z

Fixes serilog#825 - output template support for `Properties`

Fix serilog#825

63a1ceb

Attempt to Fix serilog#825

b020f4a

nblumhardt reviewed Mar 8, 2017

View reviewed changes

adamchester previously approved these changes Mar 8, 2017

View reviewed changes

Replace linq with hand-written code

ca3fc4a

nblumhardt changed the title ~~Fix #825~~ Support {Properties} in output templates Mar 10, 2017

nblumhardt reviewed Mar 10, 2017

View reviewed changes

Replace foreach with for

8012363

Do not duplicate properties already rendered in the message template.

b71576a

johnduhart reviewed Apr 4, 2017

View reviewed changes

Do not duplicate properties already rendered in the output template.

72441a9

nblumhardt reviewed Apr 5, 2017

View reviewed changes

Backward compatibility

b3c851c

Merge branch 'dev' into dev

21f77ad

nblumhardt merged commit 643dfa4 into serilog:dev Apr 5, 2017

nblumhardt mentioned this pull request Apr 6, 2017

Output template processing improvements #958

Closed

4 tasks

nblumhardt mentioned this pull request Apr 20, 2017

Fully-support {Properties} in Serilog 2.5 serilog-archive/serilog-sinks-literate#15

Closed

nblumhardt mentioned this pull request Jun 5, 2017

2.5.0 Release #980

Merged

IanYates mentioned this pull request Jan 12, 2018

Unexpected behavior when combining explicit properties with log context properties #1080

Closed

7 tasks

idubnori mentioned this pull request Aug 18, 2020

Not support property name contains dash(-) in ForContext #1479

Closed

Pchol mentioned this pull request Mar 1, 2022

Allow exclude message template properties from log serilog-contrib/serilog-sinks-graylog#77

Merged

Twinki14 pushed a commit to Twinki14/CitizenFX.Extensions.Client.Serilog that referenced this pull request Dec 30, 2023

Support {Properties} in output templates (serilog#944)

42bddf3

Fixes serilog#825 - output template support for `Properties`

Support {Properties} in output templates #944

Support {Properties} in output templates #944

Uh oh!

Conversation

Pliner commented Mar 6, 2017

Uh oh!

nblumhardt commented Mar 6, 2017

Uh oh!

Pliner commented Mar 8, 2017

Uh oh!

Pliner commented Mar 8, 2017

Uh oh!

nblumhardt Mar 8, 2017

Choose a reason for hiding this comment

Uh oh!

nblumhardt commented Mar 8, 2017

Uh oh!

adamchester left a comment

Choose a reason for hiding this comment

Uh oh!

nblumhardt commented Mar 9, 2017

Uh oh!

Pliner commented Mar 9, 2017

Uh oh!

nblumhardt Mar 10, 2017

Choose a reason for hiding this comment

Uh oh!

nblumhardt commented Mar 10, 2017

Uh oh!

Pliner commented Mar 14, 2017

Uh oh!

nblumhardt commented Mar 14, 2017

Uh oh!

Noctis- commented Mar 20, 2017

Uh oh!

nblumhardt commented Apr 2, 2017

Uh oh!

nblumhardt commented Apr 2, 2017

Uh oh!

adamchester commented Apr 2, 2017

Uh oh!

adamchester commented Apr 2, 2017

Uh oh!

merbla commented Apr 2, 2017

Uh oh!

Pliner commented Apr 3, 2017

Uh oh!

nblumhardt commented Apr 3, 2017

Uh oh!

Pliner commented Apr 4, 2017

Uh oh!

nblumhardt commented Apr 4, 2017

Uh oh!

johnduhart Apr 4, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Pliner commented Apr 5, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Pliner commented Apr 5, 2017

Uh oh!

nblumhardt Apr 5, 2017

Choose a reason for hiding this comment

Uh oh!

nblumhardt commented Apr 5, 2017

Uh oh!

Pliner commented Apr 5, 2017

Uh oh!

nblumhardt commented Apr 5, 2017

Uh oh!

adamchester commented Apr 5, 2017

Uh oh!

Uh oh!

johnduhart Apr 4, 2017 •

edited

Loading

Pliner commented Apr 5, 2017 •

edited

Loading