C#•13mo 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•13mo 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•13mo 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?

qqdev•13mo 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

JakenVeina•13mo ago

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

qqdev•13mo ago

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

JakenVeina•13mo ago

with the code you have what are you trying to accomplish

qqdev•13mo ago

Carrying additional logging info with each log output

JakenVeina•13mo ago

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

qqdev•13mo ago

Replace essentially

JakenVeina•13mo ago

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

qqdev•13mo 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•13mo 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

qqdev•13mo 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•13mo 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

qqdev•13mo 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•13mo 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

qqdev•13mo ago

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

JakenVeina•13mo 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

qqdev•13mo ago

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

JakenVeina•13mo 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

qqdev•13mo ago

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

JakenVeina•13mo 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

qqdev•13mo ago

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

JakenVeina•13mo ago

less verbose and less silly

qqdev•13mo ago

It's actually more complicated

JakenVeina•13mo ago

how so?

qqdev•13mo ago

Because imagine having like 15 props in the context

JakenVeina•13mo ago

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

qqdev•13mo ago

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

JakenVeina•13mo ago

right

qqdev•13mo ago

null props are not appended

JakenVeina•13mo 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

qqdev•13mo ago

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

JakenVeina•13mo ago

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

qqdev•13mo ago

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

JakenVeina•13mo 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

qqdev•13mo 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•13mo 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

qqdev•13mo ago

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

JakenVeina•13mo 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?

qqdev•13mo ago

The output format is JSON

JakenVeina•13mo 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•13mo 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.

qqdev•13mo ago

JakenVeina•13mo ago

also for all the others, really

qqdev•13mo ago

Interesting formatting btw pepecuke

JakenVeina•13mo ago

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

qqdev•13mo ago

JakenVeina•13mo 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

qqdev•13mo ago

The underlying logging impl takes care of that

JakenVeina•13mo ago

leaving out nulls? from the JSON?

qqdev•13mo ago

Yeah, by default

JakenVeina•13mo ago

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

qqdev•13mo ago

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

JakenVeina•13mo ago

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

qqdev•13mo ago

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

JakenVeina•13mo ago

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

qqdev•13mo ago

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

JakenVeina•13mo ago

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

qqdev•13mo 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•13mo 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

qqdev•13mo 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•13mo ago

it's not completely absurd

Accord•13mo 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.

Gaming

Programming

✅ Scoped-based logging: Microsoft interface