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’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

LogEventInfo.MessageTemplate - Subset of LogEventInfo.Properties #2262

Merged
merged 1 commit into from
Oct 2, 2017

Conversation

snakefoot
Copy link
Contributor

@snakefoot snakefoot commented Aug 23, 2017

Ordered by position (instead of hashcode).

It is possible to override these properties using the standard LogEventInfo-Properties-IDictionary-interface.

Allows capture of Microsoft FormattedLogValues without loosing the order given in the MessageTemplate. NLog/NLog.Extensions.Logging#125

@codecov
Copy link

codecov bot commented Aug 23, 2017

Codecov Report

Merging #2262 into master will increase coverage by <1%.
The diff coverage is 80%.

@@           Coverage Diff           @@
##           master   #2262    +/-   ##
=======================================
+ Coverage      82%     82%   +<1%     
=======================================
  Files         304     307     +3     
  Lines       21429   21819   +390     
  Branches     2581    2656    +75     
=======================================
+ Hits        17530   17862   +332     
- Misses       3231    3282    +51     
- Partials      668     675     +7

@snakefoot
Copy link
Contributor Author

snakefoot commented Sep 16, 2017

@304NotModified Have fixed merge conflicts, so we can continue the journey.

Please review, as I would like this before completing #2208.

@snakefoot snakefoot force-pushed the LogEventInfoMessageFormatter branch 5 times, most recently from ba79f9f to 03d5ebc Compare September 16, 2017 18:47
Copy link
Member

@304NotModified 304NotModified left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi,

What the goal here? To have a dictionary that remembers the position of the items?

Al lot of actions are now O(n)? - which is a bit unfortunate, what the use of the dictionary then ;)

I propose, add a dictionary and wrap the items in a struct/object with the index, or two dictionaries, from key -> object and key -> index.

We could create a method that gives the resulted ordered (by coping it to the array)

Correct me if I didn't understand it correctly.

}
}

private int MessagePropertiesIndexOfKey(object key)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

proposal name: GetMessagePropertiesIndex

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

{
if (_eventProperties != null && (_messageProperties == null || _messageProperties.Count == 0))
return _eventProperties.Keys;
if (_eventProperties == null && (_messageProperties == null || _messageProperties.Count == 0))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I prefer an else and nested ifs here.

Maybe also a helper for _messageProperties == null || _messageProperties.Count == 0 (9 times used?)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

/// <inheritDoc/>
public bool Remove(object key)
{
if (_eventProperties != null && _eventProperties.Remove(key))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

prefer return (_eventProperties != null && _eventProperties.Remove(key))

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

{
if (_eventEnumeratorCreated)
{
if (_eventEnumerator.MoveNext())
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

idem, return _eventEnumerator.MoveNext()

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

return true;
}
}
if (_dictionary._eventProperties != null && _dictionary._eventProperties.ContainsValue(item))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

idem, return...

{
int keyIndex = MessagePropertiesIndexOfKey(key);
if (keyIndex != -1)
throw new ArgumentException("duplicate", "key");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be nice to also include the duplicate key in the exception. We can do that in the exceptiondata or the message

return -1;
}

private static IList<KeyValuePair<string, object>> MakePropertiesUnique(IList<KeyValuePair<string, object>> value)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

please private methods below the publics

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

/// <inheritDoc/>
public void Add(object key, object value)
{
int keyIndex = MessagePropertiesIndexOfKey(key);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

so add is now O(n)?

Copy link
Contributor Author

@snakefoot snakefoot Sep 16, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Only when using structured-logging, and the key is the string-type, and there will only be a performance hit if using more than 100 message-parameters.

/// <inheritDoc/>
public void Add(KeyValuePair<object, object> item)
{
int keyIndex = MessagePropertiesIndexOfKey(item.Key);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

call the other add method?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

@304NotModified 304NotModified added this to the 4.5 milestone Sep 16, 2017
@snakefoot
Copy link
Contributor Author

snakefoot commented Sep 16, 2017

Al lot of actions are now O(n)? - which is a bit unfortunate, what the use of the dictionary then ;)

As long the number for MessageTemplateProperties is below 100 parameters, then you will not notice O(n). Normal Properties will still work as O(1).

Correct me if I didn't understand it correctly.

I want to have a property that works just like Microsofts FormattedLogValues, Serilogs MessageTemplate.Tokens / PropertyBinder.ConstructProperties or NLog StructuredEvents Template.Holes.

And using a standard array is much more optimal memory-wise than a dynamic container like a dictionary (with a positional hint). Since we have to merge two containers (user-defined-properties + message-defined-properties). Then I suggest that the message-defined-properties uses the most optimal sub-container (that doesn't loose positional information).

This new PropertiesDictionary has the special behavior that the MessageTemplateProperties comes first, so when making a message-template like "Login {user} with {password}", then the Properties-dictionary-ienumerable will return them in the positional order just like Serilog (instead of hashcode order).

@snakefoot snakefoot force-pushed the LogEventInfoMessageFormatter branch 2 times, most recently from fe4bb87 to 4af239f Compare September 17, 2017 01:04
@snakefoot
Copy link
Contributor Author

snakefoot commented Sep 17, 2017

@304NotModified Alternative then we should just leave the Properties-dictionary alone, and just create a new merged-readonly-view of Properties and MessageTemplateProperties. Then just change all locations to use the merged-readonly-view by default instead of the Properties-dictionary.

I was just in the understanding, that you wanted to minimize the number of properties-containers. Which is why I have implemented the Properties-dictionary as the merged-view.

@snakefoot snakefoot force-pushed the LogEventInfoMessageFormatter branch 2 times, most recently from b2e44f3 to 941143e Compare September 19, 2017 21:41
@snakefoot
Copy link
Contributor Author

@304NotModified Changed the PropertiesDictionary so it always allocates and uses the dictionary. This gives extra allocation for structured-logging, but gives O(1) lookup speed for both property-types.

@304NotModified
Copy link
Member

Thanks! These kind of PRs are a bit hard to review, but will try to look at it soon.

@snakefoot
Copy link
Contributor Author

Thanks! These kind of PRs are a bit hard to review, but will try to look at it soon.

It is a key-stone for the implementation of structured logging, so it mostly depends on how fast you want the structured logging up and running for NLog ver. 4.5.

@304NotModified
Copy link
Member

304NotModified commented Sep 19, 2017

Maybe a stupid question (and we discussed it before long time ago, i'm afraid),

Why do we need a separate collection for the messageProperties? Why isn't the current logeventInfo.Properties not enough? AFAIK we are missing the following features when using (only) logeventInfo.Properties:

  • the ordering of the messageProperties is lost
  • the info of what is from the template and what not is lost.

I prefer adding all properties to the current properties collection and maybe add some more metadata if we need it for the ordering.

@snakefoot
Copy link
Contributor Author

I prefer adding all properties to the current properties collection and maybe add some more metadata if we need it for the ordering.

That is what the PropertiesDictionary is doing.

@304NotModified
Copy link
Member

That is what the PropertiesDictionary is doing.

true, but i'm not keen on the logEventInfo.MessageTemplateProperties option.

Why do we need a separate collection for the messageProperties? Why isn't the current logeventInfo.Properties not enough? AFAIK we are missing the following features when using (only) logeventInfo.Properties:

the ordering of the messageProperties is lost
the info of what is from the template and what not is lost.

Is this sound and complete?

@snakefoot
Copy link
Contributor Author

snakefoot commented Sep 19, 2017

true, but i'm not keen on the logEventInfo.MessageTemplateProperties option.

You are welcome to suggest a different name, or a different approach for providing the messagetemplate-properties in the correct order.

The ordering is important, when logging to Json or a no-sql-database. NLog is not the first on the scene, and all other structured-logging frameworks take ordering serious.

@snakefoot snakefoot force-pushed the LogEventInfoMessageFormatter branch 4 times, most recently from f59ed49 to 5bbf042 Compare September 20, 2017 06:16
@304NotModified
Copy link
Member

304NotModified commented Sep 26, 2017

Have been jumping through many hoops so far, without anything being decided yet.

Sorry, it's hard to discuss things, slow-chatting and while the code evolves all the time. I prefer also a decisions/design before building stuff.

Reason why I have now reverted to introducing LogEventInfo.MessageTemplate was that you selected this solution yourself in NLog 4.5 Alpha.

I think that's the best design when the perf is good enough, just from the API point of view.

Was hoping we could continue on and stop the interface-fight, and focus on implementation.

In my opinion that's just i'm trying to do currently.

I think we not on the same line now. Sorry about that. What do we think we still have to decide?

My goal is to keep things clear and simple, I merged too much code in the past which is become "don't touch, it works" - code. Other users should have the possibility to change the code in the future.

@snakefoot
Copy link
Contributor Author

snakefoot commented Sep 26, 2017

I think we not on the same line now. Sorry about that. What do we think we still have to decide?

Well questions like "we still need the propertiesdictionary?", usually make me think that we are still stuck in the interface-decision phase :)

LogEventInfo.MessageTemplate - I think that's the best design when the perf is good enough.

Well I think the performance of this PR is good. Maybe considering to provide internal access to the actual LogEventInfo.PropertiesDictionary and change its enumerator to struct. Then the enumeration would be allocation free for the internal NLog-logic. But that optimization is for a different day.

I cheated in #2208 where I dropped the MessageTemplate completely, because of its overhead. Now the current interface allows me to have it without a serious performance hit.

I don't like political reasons for tech changes. My goal is to keep things clear and simple

Also like simple code, but I don't like open questions about design without any counter-suggestion, then one is left in the dark trying to find the light-switch.

@304NotModified
Copy link
Member

Also like simple code, but I don't like open questions about design without any counter-suggestion, then one is left in the dark trying to find the light-switch.

Fair enough. But keep in mind it's hard to give good suggestions if code is submitted which isn't clear from itself. Don't get me wrong, but it takes a lot of time to understand some parts and i'm currently have to limited time for that.

Maybe it's a better idea, that would work better for me, to create a PR with only non-optimized code (just a clear API, small changes), and in another PR a (memory optimized) change. Design is now mixed with (highy)optimized changes.

@snakefoot
Copy link
Contributor Author

snakefoot commented Sep 27, 2017

Maybe it's a better idea, that would work better for me, to create a PR with only non-optimized code

The logic that ensures LogEventInfo.Properties is a combined dictionary of both, and allows replacing of the MessageTemplate.Parameters is quite complicated. Not sure I can make it less complicated.

If you just want to see the new public API, then you just have to look at LogEventInfo.MessageTemplate. Everything else is the same.

You are welcome to present your own simple implementation of the LogEventInfo.MessageTemplate and its interaction with LogEventInfo.Properties.

You are also welcome to add code-review comments for places where the code is not very clear. The PR is less than 1000 lines of real code, so it should be manageable.

@304NotModified
Copy link
Member

hi @snakefoot

I thought about this and checked the code more in-depth.

In my opinion it's a bit strange that the LogEventInfo.MessageTemplate has a setter. I think this is a result of earlier dissensions (probably mine ;) )
Also I really like the idea behind the PropertyDictionary but as we can't use it well without breaking changes (no PropertiesDictionary Properties in LogEventInfo, I;m doubting if we really need it in a new impl.

I have a different, out-of-the-box, proposal, please let me know what you think:

Only add to the LogEventInfo:

 public IPropertiesMetaInfo PropertiesMetaInfo { get; }

Which holds the extra info which is now in the PropertiesDictionary

The interface:

    public interface IPropertiesMetaInfo : IDictionary<string, IPropertyMetaInfo>
    {
        
    }

    public interface IPropertyMetaInfo
    {
        int Position {get;}

        string Format { get; }
    }

Downside is that it's a bit more work for the client to enumerate all properties in the template, but we could add a helper (dunno where).

If you think the current design is better, I really like to know!

@snakefoot
Copy link
Contributor Author

snakefoot commented Oct 1, 2017 via email

@snakefoot
Copy link
Contributor Author

snakefoot commented Oct 1, 2017

@304NotModified I have now removed the ability to modify the MessageTemplateParameters after they have been initialized, by using a LogEventInfo-constructor. And now one can access the MessageTemplateParameters as IEnumerable (Have considered using IReadOnlyList instead for NET4_5 only, but this property will only be used on rare occacions, like with Seq).

@snakefoot snakefoot force-pushed the LogEventInfoMessageFormatter branch 2 times, most recently from 5f4f6b9 to 26cac7c Compare October 1, 2017 19:25
@304NotModified
Copy link
Member

I don't understand what you are trying to solve with your proposal besides making Nlog more difficult to use (dictionary interface is not simple).

As for the API design, it's then not clear that the templateParameters is a subset of properties.

The perfect design as we didn't need any changes to the logeventinfo, and use the logeventinfo properties. This was not the case for the position number and so I have created a new property, the metainfo (in earlier design I added it the the PropertiesDictionary, but that wasn't backwardscomp too bad).

@snakefoot
Copy link
Contributor Author

snakefoot commented Oct 1, 2017

As for the API design, it's then not clear that the templateParameters is a subset of properties.

Please review my new proposal. I think it satisfies your requirement of not having several ways to modify LogEventInfo.Properties.

LogEventInfo actually becomes the MessageTemplate, that contains Properties (These can be accessed as positional readonly properties, if available/possible).

Copy link
Member

@304NotModified 304NotModified left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK thanks, I will merge this one, some finishing comments (no API redesign)

case 9: parameterName = "9"; break;
default: parameterName = i.ToString(); break;
}
messageParameters[i] = new MessageTemplateParameter(parameterName, parameters[i], null);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

would not it been better to use yield return here? (depends on the return interface)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like for-loops better, when not needing the state-machine.

public PropertyValue(object value, bool messageProperty)
{
Value = value;
MessageProperty = messageProperty;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please rename to IsMessageProperty

new MessageTemplateParameter("Username", "John", null),
new MessageTemplateParameter("Application", "BestApplicationEver", null)
});
logEventInfo.Parameters = new object[] { "John", "BestApplicationEver", "Login request from John for BestApplicationEver" };
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This test is a bit confusing because duplicate values (john, BestApplicationEver). Is this really needed? What if we forgot one of the two?

/// <summary>
/// Gets the named parameters extracted from parsing <see cref="Message"/> as MessageTemplate
/// </summary>
public IEnumerable<MessageTemplateParameter> MessageTemplateParameters
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could we go again to our custom interface? Even if it's only implementing IEnumerable<MessageTemplateParameter>, it's more flexible for the future.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed

@snakefoot
Copy link
Contributor Author

snakefoot commented Oct 2, 2017

@304NotModified Have squashed the commits, and made the suggested changes.

Had to re-introduce the DictionaryAdapter, as I could not ensure that IEnumerable would return an enumerator of DirectoryEntry-objects.

string parameterName;
switch (i)
{
case 0: parameterName = "0"; break;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is to prevent boxing, isn't?

Copy link
Contributor Author

@snakefoot snakefoot Oct 2, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No to prevent allocation of string-objects, which int.ToString() creates.

Copy link
Member

@304NotModified 304NotModified left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks,

I added some notes for the comments. Also I have added a proposal to introduce the proxy pattern. Let me know what you think.

It's OK to me to merge first this PR and focus on docs and refactor later, I could do that if I understand the code fully (and therefor the comments)


public IDictionary EventContext { get { return _eventContextAdapter ?? (_eventContextAdapter = new DictionaryAdapter<object, object>(this)); } }

private Dictionary<object, PropertyValue> EventProperties
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These are the regular properties, isn;t?

Copy link
Contributor Author

@snakefoot snakefoot Oct 2, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure I understand the question. I moved the EventContext into the PropertiesDictionary, since there is no need for it to be on LogEventInfo.

/// The <see cref="MessageProperties" /> are returned as the first items
/// in the collection, and in positional order.
/// </summary>
internal sealed class PropertiesDictionary : IDictionary<object, object>
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

a sugesstion,

Is see a lot of special handling if isEmpty. I assume that is for more efficient memory usage.

Would a proxy design pattern be a good candidate here?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes the IsEmpty checks is to prevent extra allocations, when operating on an empty-dictionary.

if (_messageProperties != null && _messageProperties.Count > 0)
{
_eventProperties = new Dictionary<object, PropertyValue>(_messageProperties.Count);
if (!InsertMessagePropertiesIntoEmptyDictionary(_messageProperties, _eventProperties))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we need some more code if InsertMessagePropertiesIntoEmptyDictionary = false?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because then there are duplicate names, and _messageProperties must be fixed.

catch (ArgumentException)
{
// Duplicate keys found, lets try again
for (int i = 0; i < messageProperties.Count; ++i)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you explain me how remove is a try-again for add?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Have fixed the comment

eventProperties[messageProperties[i].Name] = new PropertyValue(messageProperties[i].Value, true);
if (messagePropertiesUnique != null)
{
messagePropertiesUnique.Add(messageProperties[i]);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we could simplify this code by yielding messageProperties (messageProperties[i] and messageProperties[y], what do you think?

Copy link
Contributor Author

@snakefoot snakefoot Oct 2, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Never been a big fan of yield because of the state-machine it creates.

@304NotModified 304NotModified merged commit 13a6c74 into NLog:master Oct 2, 2017
@304NotModified
Copy link
Member

merged! If you have time to response to my comments, that would be great!

@304NotModified 304NotModified modified the milestones: 4.5, 4.5 beta 4 Oct 10, 2017
@snakefoot snakefoot mentioned this pull request Nov 23, 2017
@snakefoot snakefoot modified the milestones: 4.5 beta 4, 4.5 Aug 22, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants