Custom tags missing in some contexts

[mariusz-schimke-iteo]

I'm trying to use the Sentry package in a Topshelf Windows service with Serilog handling logging. The Topshelf package lets you install and start/stop your command line app as a service by simply running the executable with arguments, e.g.

MyConsoleApp.exe install start or MyConsoleApp.exe stop.

When you run it without arguments, it starts as a command line app.

When I start the app as a service (with the start command line argument), events generated by it have no custom tags and user ID in Sentry (please see scope configuration in the code below). When I start the app without any args, the custom tags are available in Sentry.

What I investigated so far, when starting the app with the start param, the started instance starts the same executable as a Windows service and exits right away. Events logged by the initially started instance are OK in Sentry, but those logged by the service miss custom tags.

I don't know how to explain and fix it. Would you have any suggestions in this context? I would be really grateful, even though I will probably just quit Topshelf in the meantime because I have already wasted too much time without success.

Here's my .NET Framework console app code:

using Sentry;
using Sentry.Protocol;
using Serilog;
using System;
using Topshelf;

namespace ConsoleAppSentry
{
    internal class Program
    {
        private static void Main(string[] args)
        {
            var sentry = SentrySdk.Init(o =>
            {
                o.Dsn = new Dsn("my dsn");
            });

            SentrySdk.ConfigureScope(scope =>
            {
                scope.User = new User() { Id = "TestUID" };
                scope.SetTag("app.name", "Console");
            });

            Log.Logger = new LoggerConfiguration()
                .WriteTo.Sentry()
                .CreateLogger();

            Log.Logger.Error($"MAIN (CUSTOM TAGS EXIST)");

            var rc = HostFactory.Run(x =>
            {
                x.UseSerilog();

                x.Service<WindowsService>(s =>
                {
                    s.ConstructUsing(name => new WindowsService());
                    s.WhenStarted(tc => tc.Start());
                    s.WhenStopped(tc => tc.Stop());
                });

                x.RunAsLocalSystem();
                x.StartManually();

                x.SetServiceName("topshelf_test");
            });

            sentry.Dispose();

            Environment.ExitCode = (int)Convert.ChangeType(rc, rc.GetTypeCode());
        }
    }

    public class WindowsService
    {
        public void Start()
        {
            Log.Logger.Error($"START (CUSTOM TAGS MISSING)");
        }

        public void Stop()
        {
            Log.Logger.Error($"STOP (CUSTOM TAGS EXIST)");
        }
    }
}

[bruno-garcia]

My guess is that this is AsyncLocal not keeping the value since the caller (in your case Windows Service Manager) is unmanaged code. This issue happens also with IIS.

Does it happen also with .NET Framework 4.7.2?

Is it possible to initialize the SDK during Start? Instead of the constructor?
Dispose should be called on Stop in this case.
That should fix your problem.

[mariusz-schimke-iteo]

@bruno-garcia, thank you for your response. I use the Sentry package in a .NET Framework 4.7.2 service and a WPF app. I think I tried all possible combinations where to initialize it, but there was always a context where my custom tags were missing. What I eventually did is quit using Topshelf and handle service start/stop manually. I initialize Sentry in the Main method of the service, just as I did in the example in my original post.

But I call the SentrySdk.ConfigureScope method for the second time in the overriden OnStart method of the ServiceBase descendant class. I'm not sure if it is worth presenting the code (it is the standard pattern used in services). This way all events have my custom tags. I checked that by generating events on startup, on shutdown, and in class instances generated specifically in the service context.

But is that approach correct? It seems to work...

[mariusz-schimke-iteo]

But it's not all. I noticed that the WPF app I mentioned also had similar problems on shutdown. Logs generated in the Application.OnExit method also missed my custom tags. My current workaround is calling the SentrySdk.ConfigureScope in that method for the second time, before generating logs. Even though it works, I don't understand the reason why it stops working just like that, and if this solution is acceptable.

I haven't investigated that issue further, but I suspect that calling Shutdown on the App instance may be the point where custom scope configuration stops being applied to further logs.

[mariusz-schimke-iteo]

@bruno-garcia, could you please help? Let's concentrate on the WPF app now only. I noticed that some Sentry events still miss the custom tags and user ID that I set. Here's my code:

// this is the 'public partial class App : Application' class
protected override void OnStartup(StartupEventArgs e)
{
    Log.Logger = new LoggerConfiguration()
        .ReadFrom.AppSettings()
        .Destructure.UsingAttributes()
        .CreateLogger();

    SentryDatabaseLogging.UseBreadcrumbs();

    sentry = SentrySdk.Init(o =>
    {
        o.Dsn = new Dsn('my DSN');
        o.AddEntityFramework();
    });

    SentrySdk.ConfigureScope(scope =>
    {
        scope.User = new User() { Id = "a unique id of the machine" };

        scope.SetTag("app.name", Assembly.GetEntryAssembly().GetName().Name);
        scope.SetTag("app.version", Assembly.GetEntryAssembly().GetName().Version.ToString());
    });
}

Here's the Serilog config from app.config:

<appSettings>
  <add key="serilog:minimum-level" value="Verbose" />
  <add key="serilog:using:Thread" value="Serilog.Enrichers.Thread" />
  <add key="serilog:using:File" value="Serilog.Sinks.File" />
  <add key="serilog:using:Sentry" value="Sentry.Serilog" />
  <add key="serilog:enrich:WithThreadId" value="" />
  <add key="serilog:write-to:File.path" value="%LogsDirectory%\client.log" />
  <add key="serilog:write-to:File.outputTemplate" value="{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] [{ThreadId:X2}] {Message:lj}{NewLine}{Exception}" />
  <add key="serilog:write-to:Sentry.minimumBreadcrumbLevel" value="Verbose" />
  <add key="serilog:write-to:Sentry.minimumEventLevel" value="Error" />
</appSettings>

It's a multithreaded environment. The events missing the custom tags come from managed code and a different thread than the one Sentry is initialized in (if it matters). Am I doing something incorrectly or is it a bug?

[bruno-garcia]

@mariusz-schimke-iteo if you could provide us with a reproducible app, it would be great.
This way we can debug through it and find out if there's some issue with WPF and the SDK.

[mariusz-schimke-iteo]

@bruno-garcia, sure, I'll prepare one and will let you know when ready. Thanks!

[mariusz-schimke-iteo]

@bruno-garcia, sorry it took me so long, but I had no time. Here's a very simple WPF application with Sentry and Serilog integrations: SentrySerilogWpfTest.

Just set your valid DSN in the code (App.xaml.cs) and start the app, then close it. You should then get two events in Sentry: the startup event will contain the user.id and a custom tag as expected. The exit event will contain none of them.

[bruno-garcia]

@mariusz-schimke-iteo I was able to reproduce.
The problem happen because AsyncLocal value (where we keep the scope) is lost.

I found this on SO:

As pointed out in the comments, the execution context is cleared after the Loaded event. So I'm basically not trying to set the AsyncLocal before that point and expecting that to work now that I know that's not an option. Turned out I didn't really need that anyway, just wanted to know why it didn't work.

I moved the code from OnStartup to the constructor instead and it worked properly though.
Is this a viable solution for you?

[mariusz-schimke-iteo]

@bruno-garcia, sorry again for such a delay. It does not seem to solve the issue. I moved the code to the App class constructor. The OnStartup method then fails to provide user ID and tags, same case for other application contexts (such as logs generated by other threads).

[bruno-garcia]

IIRC I moved all the code to the constructor. Including setting the user to the scope.

[mariusz-schimke-iteo]

Confirmed, this is what I did too.
That question may sound stupid (I haven't analyzed Sentry code), but is AsyncLocal<> really necessary?

[bruno-garcia]

It's what is used to implicitly propagate the scope with async code

[cee-dee]

Any progress on this? I'm facing similar issues with Xilium/CefGlue where native code is involved in between. Would be nice to have support for such cases :-)

[FilipNemec]

I had the same problem on a WPF app. Regardless where the initialization was happening (Startup or constructor) because of the use of AsyncLocal the scope was sometimes lost (not always) depending on where the call was made.
To bypass this problem I call the ConfigureScope method before "logging". It seems to work fine.

[bruno-garcia]

We need to have a global shared hub/scope stack. Which we'll get to it this year :)

Tracking issue is: #628