Future of Castle logging abstraction and adapters

[jonorossi]

Extracted my comments from #404:

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). (#404 (comment))

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. (#404 (comment))

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

We need to work out a plan for how Castle libraries can log (e.g. DynamicProxy telling you about a cache miss), and how users of Windsor could possibly wire up an ILogger-like interface to become a new Windsor logging facility.

I'm using the term "abstraction" for Castle's ILogger and ILoggerFactory; "adapters" for the implementations of theses (e.g. log4net), and "facility" for the Windsor facility.

/cc @castleproject/committers

[jonorossi]

I'm thinking a library like DynamicProxy doesn't need anything big like LibLog and we just add a hook to ProxyGenerator for it to report warnings (pretty sure that is all it logs).

[stakx]

Originally posted the following regarding LibLog over in #404 (comment):

👍 to @pi3k14 for mentioning LibLog. I originally discovered it via Nicholas Blumhardt's blog article "Good citizenship - logging from .NET libraries" and, without having it taken for a spin yet, some aspects of it make good sense to me:

• Not defining our own logging abstraction, but instead using whatever the application above Castle decided on. As you said above, other logging libraries have by now surpassed Castle's own logging facilities, and there is perhaps little point in keeping it going or even inventing something brand new. My personal vote would go to deprecating Castle logging facilities, if we can find a good way to do so.

• Not being opinionated / avoiding hard static dependencies on any particular logging libraries through run-time discovery using Reflection. Following this approach would seem to make things really easy for users of Castle libraries (if we take care to keep our use of LibLog up-to-date), and it would seem that we'd no longer need the various logging library integration projects. This in turn would perhaps simplify the versioning & release process quite a bit. (I vaguely recall an episode where @Fir3pho3nixx and you had to look into this, and ended up releasing Core & all logging integration projects together and in version lockstep.)

Some things that I'm not sure about when it comes to LibLog:

• Relying on run-time Reflection seems somewhat risky. You don't know whether logging will work until you try it. Static dependencies give you more of a guarantee in that respect. This "risk" is however mitigated by the fact that the number of commonly used .NET logging libraries is probably quite small and run-time detection is entirely feasible. More arcane logging libraries would require more work to be wired up with Castle, however.

• Performance. I quickly checked, it seems that Reflection is only used for initial discovery & preparing logging delegates, but from then on logging is virtually as fast as using a logging library directly. If reflection were used for every single logging operation, that would obviously be a huge no-go.

• Fallback when no logging library is detected. Not sure what LibLog does when it fails to detect a logging library. Also not sure why it doesn't have a provider for the (admittedly horrible) logging facility built into the BCL (System.Diagnostics) but IMO this should be the fallback.

I'm by no means set on LibLog, but it does look like an interesting option to me.

@jonorossi, in response to your comment on LibLog above: I agree that it might be overkill for DynamicProxy alone, I don't recall seeing much logging in its code base (but I'll take another closer look later today). Your posts above also seem to suggest that Castle libraries may now each go their own separate way when it comes to logging—or did I misunderstand?

[jonorossi]

I agree that it might be overkill for DynamicProxy alone, I don't recall seeing much logging in its code base

Yes, DynamicProxy doesn't have much logging. I recall adding a few things quite a few years back for common scenarios where people made mistakes, e.g. not implementing Equals/GetHashCode for IProxyGenerationHook (which we could just change to throw an exception); and some debug logging for cache hits and misses (useful if you've got problems with how ProxyGenerationOptions thinks you are making proxy types).

Your posts above also seem to suggest that Castle libraries may now each go their own separate way when it comes to logging—or did I misunderstand?

Correct. I see no reason to force DynamicProxy to use the same mechanism as Windsor.

I'm by no means set on LibLog, but it does look like an interesting option to me.

Maybe we need to start by discussing how users should use Windsor without Castle's ILogger, before we look at how DynamicProxy and Windsor will stop using it?

[stakx]

Long post following -- sorry for that.

I have been thinking a bit about this. LibLog is no longer being maintained, and its creator recommends adoption of Microsoft.Extensions.Logging.

This however isn't an option as long as we want to support any target that isn't netstandard2.0 (such as net45).

Another option I've considered for DynamicProxy is System.Diagnostics.Tracing, which was once only supported on Windows (via ETW) but is now also a thing on .NET Core & Linux via dotnet trace. It would be a great match for DynamicProxy I believe, sadly that facility isn't supported on Mono at all (it's a stub that doesn't do anything there).

Another option, and perhaps not such a bad one, is to keep our own logging abstractions around, but with a few changes:

• Move ILogger and related types into a separate package Castle.Logging[.Abstractions]. Let Castle.Core and Castle.Windsor reference that package. (If we moved DynamicProxy into a separate package Castle.DynamicProxy, it would also reference Castle.Logging. Castle.Core could then become an empty meta-package referencing Logging, DynamicProxy, and DictionaryAdapter, giving the illusion that nothing changed if you reference Core -- while giving users more fine-grained control over what facilities they need.)

• Simplify the ILogger abstraction to a few methods. It really only nedds to have bool IsEnabled(LoggerLevel), void Log(string), and void Log(Exception, string). Everything else like WarningFormat(...) can be implemented on top of these using extension methods -- the implementations are likely the same for all implementations anyway (using a specific logging level value, and delegating to string.Format).

• If we do keep our own abstraction but in a changed form, perhaps we should ensure that structured logging is possible. That would likely encompass bringing a void Log(LoggerLevel, string format, params object[] args) or similar back into the interface.

For DynamicProxy I would have loved to go the System.Diagnostics.Tracing route as it would enable people to analyse structured data traces using e.g. PerfView... but the last option doesn't sound bad either.

For DynamicProxy only, we could even opt to abandon logging altogether since we only do so in about 4 or 5 code locations.

Windsor could remain largely unchanged if we kept our own logging abstraction. We might have to do a major version increase once we reference new packages though.

[stakx]

Re-reading this issue after many months away. I think I didn't quite grasp what direction @jonorossi suggested with the following two statements:

I'm thinking a library like DynamicProxy doesn't need anything big like LibLog and we just add a hook to ProxyGenerator for it to report warnings (pretty sure that is all it logs).

Maybe we need to start by discussing how users should use Windsor without Castle's ILogger, before we look at how DynamicProxy and Windsor will stop using it?

I fully agree.

I'd personally prefer not to spend too much time on Windsor, but as it's likely necessary to start there if we ever want to deprecate Castle loggers, I'll try to find some time to look into its logging.