Add trace log level

[pi3k14]

Modified logger to support Trace log in Log4Net & NLog (fallback to Debug for Serilog).

[jonorossi]

@pi3k14 this request is a bit out of nowhere. Do you intend to use it in one of the Castle libraries, or are you using Castle's ILogger in your project?

[snakefoot]

Notice Serilog has a LogLevel called Verbose

[pi3k14]

@jonorossi We are using ILogger in a project(library), and wan't to enable Trace possibilities from that.
@snakefoot Updating SerilogLogger to map Trace to Verbose.

[jonorossi]

@pi3k14 sorry about the delay, all the unrelated changes makes for a large pull request.

The changes look good, only the one comment on the console logger.

Is "trace" the right name, it seems most loggers including log4net and NLog use it, while System.Diagnostics.SourceLevels and Serilog use "verbose", however S.D.SL only has one level under info. "Trace" is probably clearer that it is lower than "debug", literally for detailed tracing turned on when needed.

@fir3pho3nixx @stakx I know we've spoken about reducing our dependence on Castle's ILogger which will take a while, but in the mean time I don't see any objection to this change. I'm assuming since you guys didn't jump in you don't mind either.

We'll need to consider how to release these changes because it'll be a breaking change to the ILogger interface.

@pi3k14 could you update the changelog. Thanks.

[stakx]

@jonorossi:

I know we've spoken about reducing our dependence on Castle's ILogger which will take a while, but in the mean time I don't see any objection to this change. I'm assuming since you guys didn't jump in you don't mind either.

I don't mind the change.

It seems to me a pity that we need to support every log level ever conceived, even when they appear redundant in some cases; feels to me as if it made the common logging abstraction fall apart. That being said, adding more log levels is probably much easier and more straightforward than investing time in devising some opaque & overly clever log level mapping.

And to be honest, I'm also not sufficiently familiar with the logging stuff to be a good judge on this. :)

[ghost]

I vehemently disagree with this. I am not happy. I won’t block this to help folks out but as maintainers we should not be in this position.

[pi3k14]

@jonorossi I added an entry in the ChangeLog, but unsure about your regime for version number and dates, please have a look.

@fir3pho3nixx, a bit unsure about what "position" you don't like to be in. But maybe the Castle project should have a look at using LibLog (or EventSourceLogger, an ILogger implementation) and throw away your own logging abstraction?

Lastly - I don't know why most of the code in this project used constructs like

public void Trace(Func<string> messageFactory)  
{  
  if (IsTraceEnabled)
  {
    Logger.Log(declaringType, Level.Trace, messageFactory.Invoke(), null);
  }
}

(I "normalized" all code to be similar)

my preferred version would be

public void Trace(Func<string> messageFactory)
{
    Logger.Log(declaringType, Level.Trace, messageFactory.Invoke(), null);
}

and let only the logger implementations perform the check for enabled log level.

Give a hint, and I can change all to the latter.

[snakefoot]

The idea is to avoid the "expensive" Invoke, when loglevel is not active

[stakx]

@pi3k14:

unsure about your regime for version number and dates

Normally all changes are initially listed under "Unreleased" heading; then when we're ready to publish a release, that title gets replaced with the actual version number and release date. That way, you as a contributor don't need to worry about version number & date at all, this will be determined by the Castle team (@jonorossi to be precise). It is also more accurate because there is no version 4.3.2 released on the 3rd, obviously. :)

I was just briefly skimming over the changes, two things I noticed:

• Is the change of DiagnosticsLogger's new default level of Trace (instead of Debug as it was previously) intentional? Not complaining, nor requesting a change, just mentioning it in case you intended to revert that one too but overlooked it.

• Please check if there's an indentation issue in SerilogLogger.cs, looks like it (but hard to tell for sure on a mobile layout).

[jonorossi]

It seems to me a pity that we need to support every log level ever conceived, even when they appear redundant in some cases; feels to me as if it made the common logging abstraction fall apart.

I vehemently disagree with this. I am not happy. I won’t block this to help folks out but as maintainers we should not be in this position.

But maybe the Castle project should have a look at using LibLog (or EventSourceLogger, an ILogger implementation) and throw away your own logging abstraction?

@stakx @fir3pho3nixx @pi3k14 you can probably tell I haven't been quick to progress this pull request, the new log level won't be used by Castle projects so only by users, this is the first time I recall this log level being proposed. The problem we've got right now is that we've discussed deprecating Castle's logging abstraction (which predates newer .NET logging, its from around 2004-2005) but haven't done anything about formalising that proposal to let people know our position and encourage users to use other libraries directly. We've briefly discussed how we could support a new logging facility for Windsor that isn't tied to the current Castle logging abstraction and would give users more freedom and not force all logging to a lowest common denominator interface (i.e. loosing structured logging when using Serilog).

@pi3k14 what logging sink/adapter are you using under the Castle abstraction?

[pi3k14]

what logging sink/adapter are you using under the Castle abstraction?

@jonorossi for the time being we are using NLog (and Log4Net), but we are also in a process to find a better solution. Not sure yet what that is going to be ... EventSourceLogger and EventFlow looks interesting though.

[jonorossi]

for the time being we are using NLog (and Log4Net), but we are also in a process to find a better solution

From my perspective, in Castle Project's prime (before 2010) users were building their applications with Windsor, MonoRail, ActiveRecord and other bits of the Castle stack so making use of the Castle logging abstraction wasn't a big thought as it just made sense; obviously most of these are now deprecated and other libraries have taken their place (i.e. ASP.NET MVC). We've been slimming down Windsor in the last year, and slowly deprecating bits dumped into what is today Castle Core.

I'm not trying to be rude just completely honest to learn how people are using it, but if you don't see the Castle logging abstraction in your project's future why are you continuing to use it today rather than just talking to NLog directly?

[pi3k14]

@stakx Fixed some space/tab glitches, corrected placement in ChangeLog. As for the Diagnostics logger I "feel" :) this is correct, but in practise it doesn't make any difference because of the simple log level mappings.

[pi3k14]

@jonorossi "Rome wasn't built in one day" :), and it isn't just our libraries/apps but also third parties (eg. ASP.NET Boilerplate) that we have custom branches of.
The problem is really with libraries/frameworks, we don't want to end up in a situation where we have to rewrite "a lot" of those because the apps switched logging (and NLog is probably not the future).

[jonorossi]

"Rome wasn't built in one day" :)

Very true 👍

[...] it isn't just our libraries/apps but also third parties (eg. ASP.NET Boilerplate) that we have custom branches of.

Oh, I didn't realise ASP.NET Boilerplate recommended using Castle's logging: https://aspnetboilerplate.com/Pages/Documents/Logging.

Since the 3 major .NET logging libraries have a log level under debug for tracing then we should probably just add it and move on. We'll separately need to start putting together our roadmap for Castle's logging abstraction and adapters, things won't happen overnight, it'll take a while to unroll things and will need to start from the top to add guidance and a new logging facility.

[stakx]

Thanks for taking a look at the following few things!

[pi3k14]

All comments should be resolved.

[snakefoot]

Think you should keep the Level-check when you can avoid string.Format call or allocation of SystemStringFormat (Same overhead as calling Invoke) This should be applied to all level-implementations

…

Sent from my Samsung device

-------- Original message -------- From: Frode Nilsen <notifications@github.com> Date: 05/09/2018 10:02 (GMT+01:00) To: castleproject/Core <Core@noreply.github.com> Cc: Rolf Kristensen <sweaty1@hotmail.com>, Mention <mention@noreply.github.com> Subject: Re: [castleproject/Core] Feature request : Support trace logging (#404) All comments should be resolved. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#404 (comment)>, or mute the thread<https://github.com/notifications/unsubscribe-auth/AK-fnE2p_IYH-n0iYhJTNs4wVjdliBEVks5uX4UqgaJpZM4V_xrW>.

[stakx]

Looks good to me now, except for one detail (see first review comment below).

[pi3k14]

@jonorossi, @stakx, @snakefoot I am holding back the last check-in until we are in agreement on what "correct" check of log levels are.
My current understanding is, use a IsTraceEnabled guard when Log function uses functors, creates new objects or use string.Format?
Only apply this rule to new methods created for Trace logging?

[snakefoot]

I think the checks should be on for all levels when it avoid allocations. When logging is not enabled.

…

Sent from my Samsung device

-------- Original message -------- From: Frode Nilsen <notifications@github.com> Date: 05/09/2018 12:15 (GMT+01:00) To: castleproject/Core <Core@noreply.github.com> Cc: Rolf Kristensen <sweaty1@hotmail.com>, Mention <mention@noreply.github.com> Subject: Re: [castleproject/Core] Feature request : Support trace logging (#404) @jonorossi<https://github.com/jonorossi>, @stakx<https://github.com/stakx>, @snakefoot<https://github.com/snakefoot> I am holding back the last check-in until we are in agreement on what "correct" check of log levels are. My current understanding is, use a IsTraceEnabled guard when Log function uses functors, creates new objects or use string.Format? Only apply this rule to new methods created for Trace logging? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#404 (comment)>, or mute the thread<https://github.com/notifications/unsubscribe-auth/AK-fnEPogY0OhOopbWCLKXLt1coCA0CBks5uX6QlgaJpZM4V_xrW>.

[jonorossi]

@stakx I've created #408, could you move your comment there.

@pi3k14 please go with whatever the other log levels do in that same scenario.

[jonorossi]

I think the checks should be on for all levels when it avoid allocations. When logging is not enabled.

@snakefoot LevelFilteredLogger already guards all log methods, it appears like most others do too.

[stakx]

All good except for the indentation in SerilogLogger.cs.

[jonorossi]

Thanks @pi3k14, apologises for so much back for forward.

@stakx before we merge, what are your thoughts on versioning for releasing this, this has a breaking change to ILogger, feels like we should be jumping another major version. If we decide to do that there are a bunch of other deprecations I've wanted to push out which we can do with that version too.

[stakx]

@jonorossi:

what are your thoughts on versioning for releasing this, this has a breaking change to ILogger, feels like we should be jumping another major version. If we decide to do that there are a bunch of other deprecations I've wanted to push out which we can do with that version too.

TL;DR: If we release a new major version (which seems reasonable to me), we should definitely include all deprecations with it to make that release a substantial one. (And if we decided in #408 to deprecate the logging facility as well, then there would possibly be no release with the new Trace stuff being added here.)

Now for some more detail.

My initial feeling was that this wasn't a big deal and would probably justify only a minor version bump—because, just how many people these days actually implement ILogger and will notice the breaking change?—but on second thought, I suppose you're right. (Like I said before, I don't know the logging facility well, I don't know Windsor well, so I'm perhaps not a good judge on the impact this change might have.)

If we wanted to turn this into a non-breaking change, we could probably go down the horrible COM route and move the new Trace-specific members to an ILogger2 interface that inherits ILogger. I anticipate that you're not a big fan of that. 😆

Which brings us back to a breaking change. My understanding is that you prefer major version releases to feel "substantial", so we should definitely include more than just the ILogger change made here. So I agree that this would be a good opportunity to get rid of things we no longer want in the public API. We could probably just remove stuff right away (instead of just marking it as [Obsolete]). Except for the ILogger things which we should probably keep, otherwise the work done here was all in vain.

If we do this, perhaps we shouldn't merge this PR just yet and wait until we're getting closer to the v5 release. Because once it's merged, it might block us from releasing a further 4.x minor version if someone requests such a one. (Say we get a request to release 4.3.2 because of #406. We'd then have to create separate release branches to exclude or revert this PR here.)

Alternatively, we could subscribe to semver's rather clinical view of major version bumps, which happen whenever there's a breaking change (however substantial or small), i.e. iterate major versions much more quickly than we have in the past. I'm not a big fan of this as humans give more meaning to version numbers than semver does, releasing new major versions every few months might just make Core look unstable.

[jonorossi]

And if we decided in #408 to deprecate the logging facility as well, then there would possibly be no release with the new Trace stuff being added here.

The logging facility is in Windsor, and the the logging abstraction isn't going away that quickly. We'd have to get everything else in place before even deprecating it (can't see it going anywhere in the next 12 months). I can guarantee there is a lot of use of these interfaces out there.

My initial feeling was that this wasn't a big deal and would probably justify only a minor version bump—because, just how many people these days actually implement ILogger and will notice the breaking change? [...]

I was actually thinking the same thing, I'd be happy with 4.4.0 for these changes, that way we'd be able to release the changes without waiting for a big bang 5.0 release.

Yer, not going down the COM-style route, i.e. ILogger2 or ILoggerEx 😆.

If we do this, perhaps we shouldn't merge this PR just yet and wait until we're getting closer to the v5 release. Because once it's merged, it might block us from releasing a further 4.x minor version if someone requests such a one.

We can always branch off a tag, but yes I'd prefer we don't have work sitting unreleased in master so long.

[...] releasing new major versions every few months might just make Core look unstable.

I've always thought the same thing especially for libraries, I know people have held back on upgrades to JSON.NET major version bumps without even looking at the changes.

My view is that you can't just change your dependencies and ship to production anyway, because any and all changes can be breaking changes even if they don't change the public API, all code changes change behaviour, and especially with Castle libraries which have sort of defaulted to everything being public the chance is even higher.

[stakx]

@jonorossi:

[...] any and all changes can be breaking changes [...]

From that perspective, choosing the version number becomes more a question of how much of a breaking change this might be. I would then say that the impact of the changes made to ILogger is probaly quite small, so a major version bump wouldn't be justified, and 4.4.0 would be OK.

Here's three ideas:

• Let's do 4.4.0 instead of 5.0.0 so we can release sooner and don't build up lots of unreleased changes.
• Consider being more explicit, in CHANGELOG.md, about this change to ILogger being a breaking change for those who implement that interface.
• Consider mentioning, at the very beginning of CHANGELOG.md, that this project uses a versioning scheme close to semver, but doesn't adhere to it in a strict fashion. (See e.g. the changelog template on Keep a Changelog which includes a similar preamble.) Basically a disclaimer so people don't blame us when they blindly upgrade dependencies using tools that expect strict semver.

[jonorossi]

Let's do 4.4.0 instead of 5.0.0 so we can release sooner and don't build up lots of unreleased changes.

👍, glad to read you agree.

Consider being more explicit, in CHANGELOG.md, about this change to ILogger being a breaking change for those who implement that interface.

This is something we've done in the past quite a bit, see the "Breaking Changes" heading under 4.1.0 last year for some minor but still breaking changes.

Consider mentioning, at the very beginning of CHANGELOG.md, that this project uses a versioning scheme close to semver, but doesn't adhere to it in a strict fashion. (See e.g. the changelog template on Keep a Changelog which includes a similar preamble.) Basically a disclaimer so people don't blame us when they blindly upgrade dependencies using tools that expect strict semver.

Interestingly I don't recall anyone complaining about us making small breaking changes in non-major versions in the past. A preamble feels a little YAGNI, if someone is taking the time to read the changelog they'll see the breaking changes section.

I guess that means we are ready to merge this and get a release out. @stakx happy?

[stakx]

@jonorossi, from my point of view, this is good to go.

[stakx]

@jonorossi:

I guess that means we are ready to merge this and get a release out.

We've let this PR sit still for a while, same goes for #419. Are you OK if we merge them both and do for a 4.4.0 release, or is there anything still missing here?

[jonorossi]

@stakx my bad, working through my Castle notifications today. Since moving back to Gmail from "Inbox by Gmail" in September, I've found myself not actioning notifications after reading them since I was using a bundle in my inbox before so always saw them, but now they get hidden, out of sight out of mind. For now I've changed the email rule not to skip my inbox.

[jonorossi]

Merged. Thanks @pi3k14, I'm normally not so slack getting pull requests merged.