Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Support {Properties} in output templates #944

Merged
merged 8 commits into from Apr 5, 2017

Conversation

Projects
None yet
6 participants
@Pliner
Copy link
Contributor

Pliner commented Mar 6, 2017

Hi guys!

Here is a small addition to the Serilog 馃槈

@nblumhardt

This comment has been minimized.

Copy link
Member

nblumhardt commented Mar 6, 2017

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

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Mar 8, 2017

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

After brief investigation I found two ways to fix it:

  1. Check MessageTemplate.NamedProperties
  2. 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

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Mar 8, 2017

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

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

This comment has been minimized.

@nblumhardt

nblumhardt Mar 8, 2017

Member

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

This comment has been minimized.

Copy link
Member

nblumhardt commented Mar 8, 2017

Looking good! Just the minor comment.

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

@adamchester
Copy link
Member

adamchester left a comment

I like it

@nblumhardt

This comment has been minimized.

Copy link
Member

nblumhardt commented Mar 9, 2017

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

@Pliner

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Mar 9, 2017

@nblumhardt I hope I fixed your comment 馃槈

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


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

This comment has been minimized.

@nblumhardt

nblumhardt Mar 10, 2017

Member

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

@nblumhardt

This comment has been minimized.

Copy link
Member

nblumhardt commented Mar 10, 2017

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

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Mar 14, 2017

@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

This comment has been minimized.

Copy link
Member

nblumhardt commented Mar 14, 2017

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-

This comment has been minimized.

Copy link

Noctis- commented Mar 20, 2017

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

@nblumhardt

This comment has been minimized.

Copy link
Member

nblumhardt commented Apr 2, 2017

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

@nblumhardt

This comment has been minimized.

Copy link
Member

nblumhardt commented Apr 2, 2017

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

@adamchester

This comment has been minimized.

Copy link
Member

adamchester commented Apr 2, 2017

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

@adamchester

This comment has been minimized.

Copy link
Member

adamchester commented Apr 2, 2017

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

@merbla

This comment has been minimized.

Copy link
Contributor

merbla commented Apr 2, 2017

Agreed, we should not duplicate.

@Pliner

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Apr 3, 2017

@nblumhardt @adamchester @merbla
Thank you for the feedback 馃槈

Will make another commit today or tomorow.

@nblumhardt

This comment has been minimized.

Copy link
Member

nblumhardt commented Apr 3, 2017

Thank you @Pliner :-) 馃憤

@Pliner

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Apr 4, 2017

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

@nblumhardt

This comment has been minimized.

Copy link
Member

nblumhardt commented Apr 4, 2017

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).

:shipit: ?

@@ -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);

This comment has been minimized.

@johnduhart

johnduhart Apr 4, 2017

Contributor

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

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Apr 5, 2017

@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

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Apr 5, 2017

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

/// <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)

This comment has been minimized.

@nblumhardt

nblumhardt Apr 5, 2017

Member

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:

  1. Keep this overload
  2. 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)
  3. 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

This comment has been minimized.

Copy link
Member

nblumhardt commented Apr 5, 2017

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

@Pliner

This comment has been minimized.

Copy link
Contributor Author

Pliner commented Apr 5, 2017

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

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

2 checks passed

continuous-integration/appveyor/pr AppVeyor build succeeded
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
@nblumhardt

This comment has been minimized.

Copy link
Member

nblumhardt commented Apr 5, 2017

馃帀 thanks for the great contribution, Yuri!

@adamchester

This comment has been minimized.

Copy link
Member

adamchester commented Apr 5, 2017

img_0054

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can鈥檛 perform that action at this time.