[FEATURE] Implement Log Level Differentiation to Reduce Verbosity and Improve Filtering

[gmij]

Description:
The current logging system outputs all events at the DEBUG level (as shown in the attached screenshot), leading to two main issues:

​Excessive log volume - High-frequency debug entries (e.g., 5+ entries within 1 millisecond) cause rapid log growth
​Poor log filtering - Critical events are buried in debug noise, making troubleshooting inefficient
Proposed Solution:
Implement log level differentiation following standard practices:

Use ​INFO level for:
• Service call initialization/entry points
• Service call completion/exit points
Reserve ​DEBUG level for:
• Detailed process tracing
• Internal state changes (e.g., cache operations shown in logs)
• Memory entry operations
Benefits:

Reduce log volume by 40-60% in normal operation (INFO level default)
Enable targeted debugging with level filtering
Improve operational visibility for key lifecycle events
Additional Context:
Attached logs show repeated DEBUG entries from the Fusion Cache component (memory operations, cache connectivity checks, and GetOrSet operations) that would be better classified as DEBUG, while missing higher-level INFO entries for service boundaries.

[jodydonetti]

Hi @gmij , missing attachments.

[gmij]

for example, the key match __fc:t:* , continue with debug. other with log level info

@jodydonetti

[gmij]

now... on log viewr, enable filter with K=__fc:t:* and K=__fc:t:! not show.
@jodydonetti

[jodydonetti]

Hi @gmij , traveling right now, will answer as soon as I can.
Thanks for sharing!

[gmij]

Ok...
Ps.
the Log Message Template is to long... the Cache Name, InstanceId, Cache Life Time ... Can Use Log Scope to record Log .
For Example :
log.BeginScope("{InstanceId}.....", InstanceId){
logger.xxx
}

[jodydonetti]

Hi @gmij I'm back on this.

Description: The current logging system outputs all events at the DEBUG level

All "main" events, yes. Some others more low level are at the TRACE level.

Proposed Solution: Implement log level differentiation following standard practices:

Use ​INFO level for:

• Service call initialization/entry points
• Service call completion/exit points
  Reserve ​DEBUG level for:
• Detailed process tracing
• Internal state changes (e.g., cache operations shown in logs)
• Memory entry operations

I've been thinking about this change from some time now, by also including TRACE level.

Let's use the last example here, where with min level TRACE we would have (simplified):

INFO: calling GetOrSetAsync<T>
TRACE: [MC] trying to get from memory
DEBUG: [MC] memory entry not found
TRACE: waiting to acquire the LOCK
TRACE: LOCK acquired
TRACE: [MC] trying to get from memory
DEBUG: [MC] memory entry not found
TRACE: [DC] trying to get entry from distributed
DEBUG: [DC] distributed entry not found
DEBUG: calling the factory (timeout=/)
DEBUG: [MC] saving memory entry
TRACE: releasing MEMORY LOCK
TRACE: MEMORY LOCK released
DEBUG: [DC] saving distributed entry
TRACE: [DC] serializing the entry
TRACE: [DC] before setting entry in distributed
TRACE: [DC] after setting entry in distributed
DEBUG: [BP] publishing set
TRACE: [BP] before sending a backplane notification (background)
TRACE: [BP] after sending a backplane notification (background)
INFO: return from GetOrSetAsync<T>

By setting min level to DEBUG we would have instead:

INFO: calling GetOrSetAsync<T>
DEBUG: [MC] memory entry not found
DEBUG: [MC] memory entry not found
DEBUG: [DC] distributed entry not found
DEBUG: calling the factory (timeout=/)
DEBUG: [MC] saving memory entry
DEBUG: [DC] saving distributed entry
DEBUG: [BP] publishing set
INFO: return from GetOrSetAsync<T>

And finally, by setting min level to INFO we would have:

INFO: calling GetOrSetAsync<T>
INFO: return from GetOrSetAsync<T>

Thoughts?

the Log Message Template is to long...
[...]Can Use Log Scope to record Log .

I feel the same, BUT: I did that because I haven't found a way so that the default experience of logging to a file/console would give enough informations in a quickly readable way so that debugging would still be easy or, at least, doable. If I remember correctly, by default scope variables is not included in the log output, so it became way less usable without them directly exposed.

[gmij]

the log level is ok.

the log message template, can try serilog , write to Console and Seq,
the Console template can print scope variables.

Add {Properties:j} to the output template to include additional context information.

https://stackoverflow.com/questions/66360594/how-do-i-include-scope-with-serilogs-console-sink-when-using-microsofts-ilogge

https://github.com/serilog/serilog/wiki/Configuration-Basics#output-templates

[bebo-dot-dev]

Jumping onto this one rather than creating another because it's in the ballpark of reducing the verbosity of logs and spans/traces.

I'm having a hard time reducing the verbosity of spans that land in DataDog that source from https://github.com/ZiggyCreatures/FusionCache/blob/main/src/ZiggyCreatures.FusionCache/Internals/Diagnostics/Activities.cs

We're not using the fusion cache OTEL lib (we can't do that yet), we're using ZiggyCreatures.FusionCache and ZiggyCreatures.FusionCache.Backplane.StackExchangeRedis 2.0.0 and the DataDog .NET sidecar which picks up these spans.

I don't mean to hijack, is there a way to disable these spans?

Edit: answering my own question. Having read the code in this project I've found that there is no native FusionCache supported way to disable the activity sources in Activities.cs when not using OTEL and the ZiggyCreatures.FusionCache.OpenTelemetry TracerProviderBuilderExtensions.

The way to do it external to FusionCache it is to ignore the FusionCache named activity sources in ActivityListener.ShouldListenTo.

This works but I think it would be nice if FusionCache natively supported this feature.

[jodydonetti]

Hi @bebo-dot-dev

We're not using the fusion cache OTEL lib (we can't do that yet)

Out of curiosity, why is that? Does it have something to do with the referenced version of OpenTelemetry.Api?

we're using ZiggyCreatures.FusionCache and ZiggyCreatures.FusionCache.Backplane.StackExchangeRedis 2.0.0 and the DataDog .NET sidecar which picks up these spans.

I don't mean to hijack, is there a way to disable these spans?

I don't know the DataDog sidecar, how does it work? Does it search for all the declared activities and automatically listen to them?

If that is the case, then the problem is there, meaning: is there a way for the sidecar to not listen to some of them?
I don't have any control over that.

Edit: answering my own question. Having read the code in this project I've found that there is no native FusionCache supported way to disable the activity sources in Activities.cs when not using OTEL and the ZiggyCreatures.FusionCache.OpenTelemetry TracerProviderBuilderExtensions.

I don't understand: activity source must be enabled to work, not disabled.
As you can see here the builder extension is adding the sources, so if you don't do that they should not be there.

Hope this helps, let me know what did I miss.

[jodydonetti]

Hi all, v2.2.0-preview-1 is out 🥳

[bebo-dot-dev]

Hey @jodydonetti, sorry for the delay replying back, I've been travelling.

Out of curiosity, why is that? Does it have something to do with the referenced version of OpenTelemetry.Api?

So the reason for us not using OTEL yet are for reasons larger than just FusionCache, we're currently working towards getting our code into a state where using/applying OTEL will be feasible across all of our services. I think if we were using OTEL today, as you highlighted TracerProviderBuilderExtensions.AddFusionCacheInstrumentation would help us out for the problem that we had but we're not quite there yet.

I don't know the DataDog sidecar, how does it work? Does it search for all the declared activities and automatically listen to them?

Yes that is how it works and it's this "listening" behaviour that was causing FusionCache activities / spans to land in DataDog.

If that is the case, then the problem is there, meaning: is there a way for the sidecar to not listen to some of them?
I don't have any control over that.

Yes this the solution that we ended up applying, we found that it's possible to exclude specific spans/traces through DataDog sidecar agent configuration (env vars), this is how we managed to stem the firehose :)

I hope what I've said makes sense but either way, all good now.

FusionCache is a truly great product, many thanks.

[jodydonetti]

Hi @bebo-dot-dev

So the reason for us not using OTEL yet are for reasons larger than just FusionCache, we're currently working towards getting our code into a state where using/applying OTEL will be feasible across all of our services. I think if we were using OTEL today, as you highlighted TracerProviderBuilderExtensions.AddFusionCacheInstrumentation would help us out for the problem that we had but we're not quite there yet.

Got it, thanks for clarifying.

Yes this the solution that we ended up applying, we found that it's possible to exclude specific spans/traces through DataDog sidecar agent configuration (env vars), this is how we managed to stem the firehose :)

Makes sense.

I hope what I've said makes sense but either way, all good now.

Oh totally, and thanks for sharing.

FusionCache is a truly great product, many thanks.

Thanks, I really appreciate that!