Topics

C#•2y ago

✅ Scoped-based logging: Microsoft interface

Hi! We are planning to make use of scoped-based logging.

using var scope1 = _logger.BeginScope(context.ToDictionary());
logContextInfomation.Foo = bar;
using var scope2 = _logger.BeginScope(context.ToDictionary());

using var scope1 = _logger.BeginScope(context.ToDictionary());
logContextInfomation.Foo = bar;
using var scope2 = _logger.BeginScope(context.ToDictionary());

We are not quite happy with this approach tho ^ Is there a less repetitive solution for this? We just want to apply the current context to every log message. Thanks in advance!

64 Replies

Zuzie•2y ago

I don't think you need to re-add the entire context to each scope, you can create a new scope with just the new context information. The parent context will still be included in the log message.

//Existing Context
using var scope1 = _logger.BeginScope(context.ToDictionary());
//New Context
using var scope2 = _logger.BeginScope(new Dictionary<string, object> {{"Foo", bar}});

//Existing Context
using var scope1 = _logger.BeginScope(context.ToDictionary());
//New Context
using var scope2 = _logger.BeginScope(new Dictionary<string, object> {{"Foo", bar}});

JakenVeina•2y ago

that is correct but like what is the actual question here?

We just want to apply the current context to every log message.

So, do that?

qqdevOP•2y ago

Thanks for your suggestions! True! That does not really help us tho, because we still have to create a new scope with every change which is very inconvenient. Was hoping that there is another way. Would be cool to see the logger keeping a reference instead of copying the context info at a specific point of time

Is there a less repetitive solution for this?

^ This

pepecoffee

JakenVeina•2y ago

for what? what is the goal to be accomplished here?

qqdevOP•2y ago

Less repetitive code Imagine changing the context information 5 times in a fn. You would have to create 5 new scopes

JakenVeina•2y ago

with the code you have what are you trying to accomplish

qqdevOP•2y ago

Carrying additional logging info with each log output

JakenVeina•2y ago

you're trying to REPLACE the context? or add additional context?

qqdevOP•2y ago

Replace essentially

JakenVeina•2y ago

what you have doesn't accomplish that and the correct solution isn't any less repetitive

qqdevOP•2y ago

The context consists of a bunch of ids basically. User id, entitiy id, etc. We want to apply that to every log msg

JakenVeina•2y ago

using(var scope1 = _logger.BeginScope(context.ToDictionary()))
{
    logContextInfomation.Foo = bar;
}
using(var scope2 = _logger.BeginScope(context.ToDictionary()))
{

}

using(var scope1 = _logger.BeginScope(context.ToDictionary()))
{
    logContextInfomation.Foo = bar;
}
using(var scope2 = _logger.BeginScope(context.ToDictionary()))
{

}

otherwise, scope2 contains everything defined in scope1 with the exception of scope vars with the same name, IIRC those will overwrite as you expect better solution....

using var userScope = _logger.BeginUserScope(context.UserId);
...
using var entityScope = _logger.BeginEntityScope(context.EntityId);
...
using var operationScope = _logger.BeginOperationScope(context.OperationId);
...

using var userScope = _logger.BeginUserScope(context.UserId);
...
using var entityScope = _logger.BeginEntityScope(context.EntityId);
...
using var operationScope = _logger.BeginOperationScope(context.OperationId);
...

etc. I.E. be more granular and just add bits to the scope as they become available

qqdevOP•2y ago

Yeah, that's basically what I was trying to avoid. Because of all the scopes you have to create We just want to log the current context info

JakenVeina•2y ago

you need a scope per new variable anywya whether you just stack them, or rebuild them each time the truth is logging code ITSELF is verbose and repetitive nothing you can really do about that

qqdevOP•2y ago

using var scope = _logger.BeginScope(context)`
context.Foo = bar;
_logger.Log(...);
context.Bar = foo;
_logger.Log(...)

using var scope = _logger.BeginScope(context)`
context.Foo = bar;
_logger.Log(...);
context.Bar = foo;
_logger.Log(...)

This would be neat. But is obv not working

JakenVeina•2y ago

best you can do is shove the bulk of the tedium out into a separate, possibly auto-generated, file that would potentially work, but absolutely do not do that take it from someone who has implemented custom ILoggerProviders within this system the logging system places NO guarantee on when logged values will actually be read from or on what thread if you pass an object to a logger, whether through .BeginScope(), or just a Log() call, and then mutate it later, you risk race conditions and exceptions

qqdevOP•2y ago

That's fine, we don't update the context in different threads

JakenVeina•2y ago

no not my point you may not, but the logging system might the logging system might be marshalling that object to a background thread in which case, it might be in the middle of reading it when you mutate it, with context.Foo = bar; which risks one of the two threads throwing

qqdevOP•2y ago

I see what you mean That would not be crucial in our case

JakenVeina•2y ago

I would even say this is relatively common the built-in console logger does this, or something very similar, in that all console I/O is buffered for thread-safety

qqdevOP•2y ago

Thanks for you help! Guess, we'll have to live with the boilerplate code or find a different approach

JakenVeina•2y ago

any provider that's sending logs out-of-process, like to a file, or a database or a logging server is probably going to be batching up logs in the background yeah IMO, your best bet for the boilerplate is to be as granular as possible

using var userScope = _logger.BeginUserScope(context.UserId);
...
using var entityScope = _logger.BeginEntityScope(context.EntityId);
...
using var operationScope = _logger.BeginOperationScope(context.OperationId);
...

using var userScope = _logger.BeginUserScope(context.UserId);
...
using var entityScope = _logger.BeginEntityScope(context.EntityId);
...
using var operationScope = _logger.BeginOperationScope(context.OperationId);
...

or just pass UserId, EntityId, etc. on a per-log-message basis depends how many you've got

qqdevOP•2y ago

What benefits does the granular approach have? Instead of replacing the whole context?

JakenVeina•2y ago

less verbose and less silly

qqdevOP•2y ago

It's actually more complicated

JakenVeina•2y ago

how so?

qqdevOP•2y ago

Because imagine having like 15 props in the context

JakenVeina•2y ago

right, but are all of those used in all scenarios? do all of those have unique lifetimes?

qqdevOP•2y ago

You pass a dictionary to the BeginScope(...) method Which contains all props

JakenVeina•2y ago

right

qqdevOP•2y ago

null props are not appended

JakenVeina•2y ago

all props currently populated and you can't pass a mutable object, so you have to snapshot the context each time it changes and dispose of the previous scope and build a new one with the new snapshot which also throws a big wrench in just your normal code flow

qqdevOP•2y ago

Yeah, would love to have a method which allows you to do that (with all the pros and cons)

JakenVeina•2y ago

uhhh you do? you already have that? what else is the purpose of .ToDictionary() in your original proposal?

qqdevOP•2y ago

The dictionary is not mutable, it is created on the fly

JakenVeina•2y ago

correct that's what I just said

using(var scope = _logger.BeginScope(context.ToDictionary()))
{
    var queryResult = await PerformQueryAsync();
    context.UserId = queryResult.UserId;
    // context has changed, have to re-build the logger scope now
}
using(var scope = _logger.BeginScope(context.ToDictionary()))
{
    // queryResult is now out-of-scope, even though we haven't had a chance to DO anything with it yet
}

using(var scope = _logger.BeginScope(context.ToDictionary()))
{
    var queryResult = await PerformQueryAsync();
    context.UserId = queryResult.UserId;
    // context has changed, have to re-build the logger scope now
}
using(var scope = _logger.BeginScope(context.ToDictionary()))
{
    // queryResult is now out-of-scope, even though we haven't had a chance to DO anything with it yet
}

as opposed to

using var initialScope = _logger.BeginScope(...);

var queryResult = await PerformQueryAsync();
context.UserId = queryResult.UserId;
using var userScope = _logger.BeginScope(context.UserId));

// Do stuff

using var initialScope = _logger.BeginScope(...);

var queryResult = await PerformQueryAsync();
context.UserId = queryResult.UserId;
using var userScope = _logger.BeginScope(context.UserId));

// Do stuff

qqdevOP•2y ago

I don't really get your point then. Because your examples show that only a snapshot is used ty, for your help! I think we kinda go in circles here, seems like there is no obv solution to our issue

JakenVeina•2y ago

I'm... not saying you don't need one not in your "rebuild the entire scope each time" solution you definitely need to snapshot the context if you're passing the whole thing to any logger calls I'm saying if it were me, I wouldn't pass the whole thing I would just declare a scope for individual properties on the context, as they become available alternative #2, setup your context object as a thread-safe collection, so you can pass the whole thing to .BeginScope() and it's the collection itself that will effectively snapshot itself when the logger attempts to read it that should at least avoid thread-safety issues, although it could result in some props appearing or not appearing in logs in an unexpected way

qqdevOP•2y ago

Yeah, that's also what I was thinking of while chatting in this thread. Might be worth a try

JakenVeina•2y ago

alternative #3, if you're gonna snapshot the context each time it's needed, just do that per-log if it really changes frequently enough that creating scopes for each change is unfeasible, then it sounds like you probably don't want to scope-ify it how are you encoding all of this data, BTW? if all 15 props on the context are populated, what does a log of that context look like?

qqdevOP•2y ago

The output format is JSON

JakenVeina•2y ago

well, I suppose what you're effectively doing is structuralizing these values yourself via .ToDictionary() it's IEnumerable<KeyValuePair<string, object>> that the logger recognizes as structured log data, yeah? which .ToDictionary() produces yeah point I'm getting at is for alternative #3, you might find this helpful

JakenVeina•2y ago

https://github.com/JakenVeina/StructuredLoggerMessage

GitHub

GitHub - JakenVeina/StructuredLoggerMessage: A library for high-per...

A library for high-performance structural logging. - GitHub - JakenVeina/StructuredLoggerMessage: A library for high-performance structural logging.

qqdevOP•2y ago

ty

JakenVeina•2y ago

also for all the others, really

qqdevOP•2y ago

Interesting formatting btw pepecuke

pepecuke

JakenVeina•2y ago

that provides effectively another way to snapshot the whole context which bit?

qqdevOP•2y ago

JakenVeina•2y ago

oh, yeah wish more people would prioritize human readability in code formatting as a side note, I would personally probably say it's a waste of time to try and filter out the null values of the context, for logging was the UserId at the time of the log null, I.E. not yet known? that's important leaving out nulls, in my mind, is really an optimization in logging traffic on the network (or wherever they're going) and is a setting that the log serializer should support

qqdevOP•2y ago

The underlying logging impl takes care of that

JakenVeina•2y ago

leaving out nulls? from the JSON?

qqdevOP•2y ago

Yeah, by default

JakenVeina•2y ago

well, then why are we spending so much effort trying to pre-filter them out?

qqdevOP•2y ago

Keeps the JSON clean Uhm, I was just trying to solve the boilerplate issue ;D

JakenVeina•2y ago

well but, like okay, nevermind it's not about filtering nulls, it's about capturing the new non-null values when they change

qqdevOP•2y ago

We basically want to capture every change Even when it goes back to null Just a plain ass simple logging pepelaff

pepelaff

JakenVeina•2y ago

yeah, I would say don't scope it, then that INTRODUCES extra boilerplate to handle changing scopes when the context changes unfortunately

qqdevOP•2y ago

The concept itself makes sense but the current impl of it does not allow us to what we want

JakenVeina•2y ago

this sounds like "pass it to each separate Log() call" to me

qqdevOP•2y ago

Imagine just putting in the context and everything in the context is appended to the log messages (within the scope) That would be sick

JakenVeina•2y ago

if you wanna try and explore having the context be thread-safe for that purpose, go for it just be aware that risks "incorrect" logs

qqdevOP•2y ago

I am currently thinking of creating a custom logger class which wraps all methods Where you could assign the context to it and it abstracts passing the context to every log message away Which is your #3 I guess Would have to act as a drop-in replacement for the current logging tho (DI friendly)

JakenVeina•2y ago

it's not completely absurd

Accord•2y ago

Was this issue resolved? If so, run /close - otherwise I will mark this as stale and this post will be archived until there is new activity.

We are a programming server aimed at coders discussing everything related to C# (CSharp) and .NET.

54KMembers

View on Discord

Want results from more Discord servers?

Add your server