NLog.PushProperty: Share state between PreRequest Filter and Service

#1

Hi,
NLog provides a feature to PushProperty into the ScopeContext (https://github.com/NLog/NLog/wiki/Context#scopecontext-properties).

We want to add e.g. the user-id to this scope context on a request level, so that every log statement within a service has this user-id property.

The idea was to use pre request filter to add the property to the scope context. Because PushProperty is a disposable, we store that IDisposable in IRequest.Items, just to be able to Dispose it in a ResponseFilter.

Sample Code:

public static class UserLoggingContextFilter
{
    public const string ContextKey = "user-log-context";

    public static void RequestFilter(IRequest request, IResponse response, object _)
    {
        var session = (AuthUserSession) request.GetSession();
        
        request.Items[ContextKey] = ScopeContext.PushProperties(new[]
        {
            new KeyValuePair<string, object>("UserId", session.UserAuthId),
            new KeyValuePair<string, object>("UserName", session.UserName),
            new KeyValuePair<string, object>("Session", session.Id[..6]),
        });
    }
    
    public static void ResponseFilter(IRequest request, IResponse response, object _)
    {            
        (request.Items[ContextKey] as IDisposable)?.Dispose();
    }
}

We noticed that Properties added in the RequestFilter aren’t visibile in the Service and were wondering why this is the case?

It seems that the RequestFilter and service implementation doesn’t share the same ScopeContext. As far as we understand ScopeContext uses AsyncLocal as storage.

Overrideing ServiceRunner.OnBeforeExecute to push properties there works.

We’re expecting to be able such Context between PreRequestFilters and the service implementation. What am I missing? I couldn’t figure it out in the docs.

#2

ServiceStack uses the same IRequest instance passed in your Request Filters that is passed into your Service so anything added in IRequest.Items should be accessible, we’d need a repro if you want us to investigate why this isn’t happening in your case.

Which ScopeContext are you referring to? There’s no such class in ServiceStack.

Note ServiceStack already disposes all IDisposable's stored in Request.Items at the end of the request (in its AppHost.OnEndRequest()) so you wouldn’t need to manually dispose it yourself.

#3

ScopeContext is from NLog and uses internally System.Threading.AsyncLocal to store state. Thats why i did expect to be able to share async local state.

Thank you for this hint.

#4

Ok that sounds like an NLog implementation detail, not clear on what the implied reference to ServiceStack is though and not sure how this would affect the IRequest instance passed through ServiceStack’s Request pipeline, are you trying to reference the HttpContext from a singleton context somewhere?

#5

We also try to figure out with the NLog github repo. Docs are unfortunately very unclear there.

if we do the same thing in a CustomServiceRunner e.g.:

public override void OnBeforeExecute(IRequest req, T request, object service)
{
    var session = req.GetSession();

    var context = ScopeContext.PushProperties(new[]
    {
        new KeyValuePair<string, object>("UserName", session.UserName),
        new KeyValuePair<string, object>("UserId", session.UserAuthId),
        new KeyValuePair<string, object>("Session", session.Id[..6]),
    });
    
    req.Items["nlog-disposes"] = context;

    base.OnBeforeExecute(req, request, service);
}

it actually works as expected.

debugging the ServiceRunner, PreRequestFilter and the ServiceImplementation i clearly see that everything is done in the same Thread.

so for me it’s not clear whats the difference between ServiceRunner vs RequestFilter that actually makes this not work in the RequestFilter.

#6

I’m assuming it’s going to be due to an async hop somewhere when awaiting an async method which shouldn’t be an issue with AsyncLocal that should be tracking the logical thread.

What version of ServiceStack + .NET Version are you using?

#7

ServiceStack 6.3.1 and .NET 6.0

i could upgrade to 6.4.1 and .NET 7.0 to see if this fixes it

#8

I’d wait 1hr, about to publish v6.5…

#9

same behavior with v6.5

#10

Yeah I didn’t expect there to be any behavioral differences, I’d still like to know why setting IRequest.Items in a Request Filter isn’t available throughout the Request Pipeline.

Where is UserLoggingContextFilter registered in the Request Pipeline? Does it happen if you set a string, e.g. Request.Items["test-id"] = Guid.NewGuid().ToString()?

Where does it lost, is the Item set in a Request Filter not available in OnBeforeExecute()?

#11

i hooked host.GlobalRequestFilters.Add() and a host.PreRequestFIlters.Add().

In both hooks i did

  • set something to Request.Items
  • ScopeContext.PushProperty (from NLOG)

In the debugger of the service handling a request dto i find Request.Items added from GlobalRequestFilters and PreRequest filter -> works as expected.

But the ScopeContext only contains the property added by the PreRequestFilters and not the GlobalRequestFilters.

Do you understand what might influence the different behavior of PreRequestFilters/GlobalRequest filters?

#12

Ok this should confirm that the same IRequest instance is being passed through the Request Pipeline.

There’s nothing different about the RequestFilters, as mentioned previously the behavior is going to be as a result of the async hops, i.e. after using async/await, the rest of the async method continuation can be executed by another thread which is why AsyncLocal should be used in async methods instead of Thread Local storage so the attached storage follows the logical thread.

If it has access to the property added by PreRequestFilters it sounds like you can add a complex type to Request.Items in the PreRequestFilters that you can access & populate in GlobalRequestFilters, i.e. so you’re modifying an existing instance instead of pushing new ScopeContext properties in the GlobalRequestFilter.