[FEATURE] Ability to have less information in log messages

[tvardero]

Problem

Log lines are cluttered with information which does not make sense or gives little value:

FUSION [N=FusionCache I=0HNIUCQDRINEH] (O=0HNIUCQDRJAN3 K=gl-backend:metabase_embed_token_114af5e7-8cc3-482d-c61f-08dc99d9cda8_efd0d1d4-df7d-4758-4388-08dc58846adc_1b97c5d0-109a-4960-8e18-08dc593ca882): FailSafeMaxDuration 02:00:00 was lower than the Duration 06:00:00 on FEO[DUR=06:00:00 LKTO=/ SKMR=N SKMW=N SKDR=N SKDW=N SKDRWS=N DDUR=/ JIT=2s PR=N SZ=/ FS=Y FSMAX=02:00:00 DFSMAX=/ FSTHR=30s FSTO=5s FHTO=5s TOFC=N DSTO=1s DHTO=2s ABDO=N SBN=N ABBO=Y AC=N]. Duration has been used instead.

It hides meaningful information way far horizontally, and requires horizontal scroll to see them.

Instead it should have been just

FailSafeMaxDuration 02:00:00 was lower than the Duration 06:00:00. Duration has been used instead.

Those configuration values (DSTO=1s DHTO=2s ABDO=N etc.) I could find myself when needed by looking through my codebase.

Solution

Option in options to have less verbose log messages.

Extended debug information should be disabled by default (breaking!) in my opinion.

Alternatives

Disabling fusioncache logs (setting log filter to Fatal)

[tvardero]

My config:

    public static IHostApplicationBuilder AddAppHybridCache(this IHostApplicationBuilder builder)
    {
        // see docs https://github.com/ZiggyCreatures/FusionCache/blob/main/docs/StepByStep.md
        IFusionCacheBuilder fusion = builder.Services.AddFusionCache()
            .AsHybridCache()
            .WithCacheKeyPrefix("gl-backend:")
            .WithOptions(o =>
            {
                o.DistributedCacheCircuitBreakerDuration = TimeSpan.FromSeconds(30);
                o.AutoRecoveryMaxRetryCount = 20;
            })
            .WithDefaultEntryOptions(o =>
            {
                // cache entry duration
                o.Duration = TimeSpan.FromMinutes(1);
                o.JitterMaxDuration = TimeSpan.FromSeconds(2);

                // entry factory failsafe
                o.IsFailSafeEnabled = true;
                o.FailSafeMaxDuration = TimeSpan.FromHours(2);
                o.FailSafeThrottleDuration = TimeSpan.FromSeconds(30);

                // entry factory soft-hard timeouts
                // WARN: do not set different timeouts for soft and hard — factory might capture DbContext in closure, and on the soft timeout will
                // return to caller without terminating factory. DbContext does not support parallel operations — this will lead to exceptions.
                o.FactorySoftTimeout = TimeSpan.FromSeconds(5);
                o.FactoryHardTimeout = TimeSpan.FromSeconds(5);
                o.AllowTimedOutFactoryBackgroundCompletion = false;

                // distributed cache soft-hard timeouts
                o.DistributedCacheSoftTimeout = TimeSpan.FromSeconds(1);
                o.DistributedCacheHardTimeout = TimeSpan.FromSeconds(2);
                o.AllowBackgroundDistributedCacheOperations = false;
            })
            .WithSystemTextJsonSerializer(new JsonSerializerOptions { ReferenceHandler = ReferenceHandler.IgnoreCycles });

        builder.Services.ConfigureOpenTelemetryTracerProvider(t => t.AddFusionCacheInstrumentation());
        builder.Services.ConfigureOpenTelemetryMeterProvider(m => m.AddFusionCacheInstrumentation());

        string? redisConnectionString = builder.Configuration.GetConnectionString("Redis");
        if (!string.IsNullOrEmpty(redisConnectionString))
        {
            builder.Services.AddStackExchangeRedisCache(c => { c.Configuration = redisConnectionString; });

            fusion.WithRegisteredDistributedCache();
            fusion.WithBackplane(new RedisBackplane(new RedisBackplaneOptions { Configuration = redisConnectionString }));

            builder.Services.AddHealthChecks()
                .AddRedis(redisConnectionString, failureStatus: HealthStatus.Degraded);

            builder.Services.ConfigureOpenTelemetryTracerProvider(t => t.AddRedisInstrumentation());
        }

        return builder;
    }

[jodydonetti]

Hi @tvardero , I feel you: logging is quite the topic which is apparently easy but with a lot of different shades and opinions on what is "right".

Having said that, the main point here in particular is just a mistake on my end: I should have put that last part ("Duration has been used instead") before the "nonsense part", I'll definitely fix this soon.

And about the "nonsense part": I agree it's not particularly beautiful to look at, but it was a way to have a short/dense message with a lot of important information inside, without relying on property bags which, by default, do not show up in (text/console based) log output.

Anyway, I'm in the process on doing a pretty big overhaul of the entire logging part of FusionCache, and there are already quite a bit of tasks I'm looking at, so I've added this too to the list.

I'll post here a link to the issue with the proposed design as soon as I can.

Thanks for sharing your point of view.