ILogger for ConnectionMultiplexer

[NickCraver]

ILogger support - since we support Action<ConfigurationOptions> this can be added today e.g. with o => o.LoggerFactory = myLoggerFactory:

var muxer = ConnectionMultiplexer.Connect("localhost", o => o.LoggerFactory = myLoggerFactory);

...or we could add sibling overloads to the existing TextWriter. I'd love to not create a ^2 matrix every time we do this, though. Starting simpler for that reason. Note: this is on top of #2050 for simplicity, will roll against main when merged.

TODOs here:

• General sanity check
• Overloads decision
• Tests of this implementation
• Seeing which additional things need logging, we should make a list and check it here.
• How do we make these calls the most efficient?
• Do we eat the overhead for structured logging?

[NickCraver]

Should add to the default options as well

[mgravell]

how do we feel about allocations and log-levels? there are the stateful callback APIs that avoid allocs / formats when the log level turns out to be too low, although these take a very different shape, i.e.

log.Log(LogLevel.Information, default, (name, id), null, static (state, _) => $"Thing {state.name} of {state.id}");

(can be simplified quite a bit by using local extension methods)

if we don't care, that's also fine, as long as deliberate

[NickCraver]

There are a few ways to make this faster on allocations - totally cool with any of them my thinking is:

1. It should be analyzer enforced if possible
2. It should work everywhere possible.

There exists today the signatures like LogInformation(ILogger, String, Object[]) and friends, but if we're formatting that message at all it's the same performance plus the object array in the end to get structured logging.

I was really hoping before tackling this that the interpolated string handler goodness in .NET 6+ (https://devblogs.microsoft.com/dotnet/string-interpolation-in-c-10-and-net-6/) would have landed in logging extension methods but alas this set of APIs didn't happen. I chatted with @stephentoub on this quite a while back and did poke at it, but the fundamental problem you arrive at is "that's not the shape of ILogger" in the end, so if that's your interface someone is calling the formatter in all the cases I could try to be more efficient in. It's entirely possible a smarter API design that I was capable of would still be a win here though, and if so: I'm all game for it.

In the example above my worry cases would be "touching ValueTuple again with a 1000 ft pole" and exceedingly high format count cases to maintain like exception messages today with something like 30-50+ args in play.

I'll keep hacking at making all the basics correct here, but if we can come up with optimal paths to go back through: yeah, absolutely. Do you wanna try a spike against this branch and see what we can do for options? Absolutely wanting to make this more efficient if we reasonably can.

[petrroll]

Apart from using stateful callback APIs that avoid allocations, providing Logging API with template + values for holes instead of pre-interpolated strings enables structured logging.

I.e.

logging.Log?.LogInfo($"Response from {bridge?.Name} / {message.CommandAndKey}: {result}");

vs

logging.Log?.LogInfo("Response from {bridgeName} / {messageCommandAndKey}: {result}", bridge?.Name, message.CommandAndKey, result);

See more: (https://learn.microsoft.com/en-us/dotnet/core/extensions/logging?tabs=command-line#log-message-template or aka.ms/r9 (internal only) and search structured logging).

There's a push (internally, at least in some orgs) towards structured logging so if it was possible to support that, it'd be doubly awesome :).

[petrroll]

Ofc, the change 'd need to be made in LogProxy and threaded through all layers.

[NickCraver]

This is true, but it's also more expensive at every call site (due to the allocation of the object[] array at the end). Ideally we could enable structure logging without the overhead :-/ I'm not against structured logging - tons of uses, but it's odd to me that logging is such a performance hog across so much and there isn't an easier path that's also efficient here. Hoping we continue to see that improve in the coming .NET releases if we can push a bit on logging APIs. ILogger's shape makes that hard though, when realizing wins through the pipe.

[petrroll]

It's more expensive at every call site when the logging actually goes trough, i.e. for levels that are enabled. But for log-calls that don't end up being used (loglevel, ...), you don't pay for interpolating the strict, which I'd guess would be roughly similar to the cost or higher than allocating object[] array.

That said, the benefit then depends on the expected ratio of "taken" and "not-taken" log-sites.

[NickCraver]

If you have a logger at all, it's almost certainly to go through here. We're already null checking against that, so we've solved the first problem and moved on to the second. In our case, because of the elvis approach, it' universally more expensive :)

[petrroll]

Ah right, brain-fart on my side 😅. The array needs to be allocated always. In that case I see how it's a performance negative.

[stebet]

Do the Source Generated logger messages help here? I admit I haven't looked at them properly. https://learn.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator

[davidfowl]

More info here: https://github.com/dotnet/designs/blob/main/accepted/2021/logging-generator.md#supporting-string-interpolation-builder-in-logging

[NickCraver]

More info here: dotnet/designs@main/accepted/2021/logging-generator.md#supporting-string-interpolation-builder-in-logging

@davidfowl thanks! I'm still unclear of the status (is it still a proposal/design, or landed?). Overall: we're going to go with the current non-optimal (but also non-hot path) approach to get this in, but open to optimizing it more later. I think we should also get some proper event IDs going and refine a bit overall there too to be a decent example - that is definitely something I'd like as well querying Kusto daily.

The method-per-line boilerplate approach on some of the current methods is definitely what I'm most averse too, that's a lot of maintenance overhead to optimize cold paths. Proposals to remove that and allow an inline call to be optimize (as it is with existing StringBuilder usage) is very appealing. If it's still in proposal, happy to help make the case for it.

[davidfowl]

The method-per-line boilerplate approach on some of the current methods is definitely what I'm most averse too, that's a lot of maintenance overhead to optimize cold paths. Proposals to remove that and allow an inline call to be optimize (as it is with existing StringBuilder usage) is very appealing. If it's still in proposal, happy to help make the case for it.

You should treat logs with a similar level of rigor as public API. I think the source generator helps you manage that. Sure, it's more boilerplate but it's actually very important for libraries to be more careful with how they manage event ids and log levels. Same goes for metrics and other diagnostics information.

[NickCraver]

I'm not sure I can agree with that in all areas - we find new things to log and add all the time from scenarios people haven't hit before. Happy to chat more on this, but if you look at the history of our logging here that's been the case for most additions, and adding more useful logs for example in the log of connecting to the server is going to get additions and changes not nearly as strict as a public API. Exception messages are also an extreme version of this - we add a ton of information necessary to help debug there, because all we get in an issue as library authors is often just that message, so it's intentionally pretty crammed full of stats - I wouldn't consider that anywhere near as stable as public API (which we take very seriously).

I think we may have 2 different things in mind here. For things like events, exceptions, etc. I do not think the boilerplate or methods or events are onerous - I think it's fine. In the places we're say logging 50-100 lines of a connection logs: that's kinda crazy levels of overhead to me. What are your thoughts on that area? That's where I don't see the current advice fitting well (but is also probably a pretty rare use case). What implementation do you picture there as being ideal?

For a concrete example, check out ReconfigureAsync which is almost entirely that kind of log stream - thoughts? https://github.com/StackExchange/StackExchange.Redis/pull/2051/files#diff-b874d835cf9aa762b0e52adf8c37c2ed87b244f10dd36749ffdf735f0aea0e53R1397

[mgravell]

I like it

[AlexanderKot]

Hello all
When using StackExchange.Redis with
StackExchange.Redis.Extensions RedisConnectionPoolManager
It is not possible to use new LoggerFactory feature, because RedisConnectionPoolManager create redis connection inside, and initialized by RedisConfiguration class. And RedisConfiguration cannot deserialise LoggerFactory from string representation.

Is this issue for StackExchange.Redis project or for StackExchange.Redis.Extensions?

[NickCraver]

@AlexanderKot Thats definitely an issue for them - we have zero control over that package :)

[AlexanderKot]

Thank you
I was not attentive enough and decided that RedisConfiguration for your code base - i was wrong, it is also from Extensions

[AlexanderKot]

But it is not so trivial
RedisConfiguration inside use
newOptions = ConfigurationOptions.Parse(ConnectionString); //This options will be used for connection
ConfigurationOptions from StackExchange.Redis codebase.
It do clone of LoggerFactory, but cannot initialize it in Parse.
So question seems opened

[pairbit]

Nooo what have you done. Why did you make a dependency on Microsoft.Extensions.Logging.Abstractions???
I cried when I saw this :(((

[davidfowl]

That's a fine dependency 😄

[NickCraver]

Nooo what have you done. Why did you make a dependency on Microsoft.Extensions.Logging.Abstractions??? I cried when I saw this :(((

To log stuff, mainly...

Note that as I'm writing this that package has 3.7 billion downloads, which means this isn't a net new dependency for likely the vast majority of users.

[pairbit]

right now I made a fork without the dependency Microsoft.Extensions.Logging.Abstractions. The fact is that Microsoft.Extensions.Logging.LoggerExtensions are very bad, they are prohibited from being used in our projects.

Please create your own IRedisLogger interface without params object[]. Also replace the ILoggerFactory type with the Func<Type,IRedisLogger> delegate.

I created a ticket, please do not close it immediately. Consider my proposal. Thank you

[NickCraver]

@pairbit Are we using the params overload somewhere I'm not seeing? We very much go out of our way to keep things efficient, so if you have a specific thing to point to I'm all ears. "Please break your API because I don't like this thing" isn't about efficiency though - this is something that's extremely pervasive in the ecosystem and allows most devs to discover issues more easily - that's worth a dependency to me. Every dev having to write basically the same adapter or include 2 packages doesn't ultimately remove a package (including this package) or enhance the user experience.

For what it's worth, I would love to see codegen improvements for those other areas of the logging interfaces (as was done with StringBuilder), and sincerely hope that happens.

[pairbit]

@NickCraver You don't use methods with an objects parameter.
I described this on the ticket.
Your library managed without this dependency for 9 years.
And I still don’t understand why you had to add a whole dependency for the sake of one Log method, which is not the main one in your library.

I understand that my request is probably too petty.
Thank you for your time, my task was to try to convince you.

[niemyjski]

Seems like a lot of these logging levels should have been LogDebug or LogTrace

[NickCraver]

Based on what? This is a core part of connecting to the server, knowing which IP we connected to is definitely information level in my mind. I'm open to adjusting these of course, but don't agree with the specific thing commented on here. I think most people would default to only-errors for StackExchange.Redis, but anything beneath that like connecting when we're a client with a persistent connection is, IMO, information level.

[niemyjski]

I agree it could be important and can see if your only logging / interaction is with this library you might prefer it. However, most apps don't need this kind of logging by default and just adds to the noise as the default log level is info

But if you are having connectivity issues you are probably going down to the debug or trace levels anyways. Based on default out of the box log levels. Also, for most people this information is not needed and might even be a possible security concern leaking information about services (log collection tends to have different roles and policies which are more frequently granted to more individuals).

I can see your point about default log level being Error, perhaps we should call that out in the Readme?