Quartznet: Bug: Quartz.NET throws unhandled Exception when .net core 3.1 debugging flags are enabled

[Pinguwien]

Describe the bug

I am using .net core 3.1 and Quartz 3.3.2 here and sadly have a problem where I hope you can help me out with:

On a high level, my dockerized asp.net application always throws an unhandled exception when first calling the execute method of my only impl of IJob interface (so far). If running locally, the exception does not occur.

I followed the tutorial given by andrew lock here:
https://andrewlock.net/creating-a-quartz-net-hosted-service-with-asp-net-core/

My program.cs Hostbuilder now looks like this:

...
Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                })
                .ConfigureLogging((hostingContext, logging) =>
                {
                    ...
                })
                .UseNLog()
                .ConfigureServices(
                    (hostContext, services) =>
                    {
                        services.AddHostedService<OtherHostedServiceWithoutQuartz>();

                        // Add the required Quartz.NET services
                        services.AddQuartz(quartzConfig =>
                        {
                            quartzConfig.SchedulerId = "my-scheduler";
                            quartzConfig.SchedulerName = "MyScheduler";
                            quartzConfig.UseDefaultThreadPool(options => options.MaxConcurrency = 3);

                            // tells Quartz.NET to register an IJobFactory that creates jobs for transient, scoped or singleton services by fetching them from the DI container.
                            quartzConfigurator.AddJobAndTrigger<MyJob>(
                                hostContext.Configuration);
                        });

                        // Add the Quartz.NET hosted service and allow graceful shutdown.
                        services.AddQuartzHostedService(options => options.WaitForJobsToComplete = true);
                    });

So, I get the following exception log when starting my service inside docker:

2021-05-05 09:11:24.2691 | DEBUG | Calling Execute on job DEFAULT.MyJob 
2021-05-05 09:11:24.2737 | ERROR | Job DEFAULT.MyJob threw an unhandled Exception:  System.InvalidOperationException: Not a recovering job
   at Quartz.Impl.JobExecutionContextImpl.get_RecoveringTriggerKey()
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.PropertyFetch.RefTypedFetchProperty`2.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.Morph(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.Morph(Object args)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_1.<.ctor>b__2(KeyValuePair`2 evnt)
   at System.Diagnostics.DiagnosticSourceEventSource.CallbackObserver`1.OnNext(T value)
   at System.Diagnostics.DiagnosticListener.Write(String name, Object value)
   at System.Diagnostics.DiagnosticSource.StartActivity(Activity activity, Object args)
   at Quartz.Logging.JobDiagnosticsWriter.WriteStarted(IJobExecutionContext context, DateTimeOffset startTimeUtc)
   at Quartz.Core.JobRunShell.Run(CancellationToken cancellationToken)
2021-05-05 09:11:24.3217 | ERROR | Job DEFAULT.MyJob threw an exception. Quartz.SchedulerException: Job threw an unhandled exception.
 ---> System.InvalidOperationException: Not a recovering job
   at Quartz.Impl.JobExecutionContextImpl.get_RecoveringTriggerKey()
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.PropertyFetch.RefTypedFetchProperty`2.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.Morph(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.Morph(Object args)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_1.<.ctor>b__2(KeyValuePair`2 evnt)
   at System.Diagnostics.DiagnosticSourceEventSource.CallbackObserver`1.OnNext(T value)
   at System.Diagnostics.DiagnosticListener.Write(String name, Object value)
   at System.Diagnostics.DiagnosticSource.StartActivity(Activity activity, Object args)
   at Quartz.Logging.JobDiagnosticsWriter.WriteStarted(IJobExecutionContext context, DateTimeOffset startTimeUtc)
   at Quartz.Core.JobRunShell.Run(CancellationToken cancellationToken)
   --- End of inner exception stack trace --- [See nested exception: System.InvalidOperationException: Not a recovering job
   at Quartz.Impl.JobExecutionContextImpl.get_RecoveringTriggerKey()
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.PropertyFetch.RefTypedFetchProperty`2.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.Morph(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.Morph(Object args)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_1.<.ctor>b__2(KeyValuePair`2 evnt)
   at System.Diagnostics.DiagnosticSourceEventSource.CallbackObserver`1.OnNext(T value)
   at System.Diagnostics.DiagnosticListener.Write(String name, Object value)
   at System.Diagnostics.DiagnosticSource.StartActivity(Activity activity, Object args)
   at Quartz.Logging.JobDiagnosticsWriter.WriteStarted(IJobExecutionContext context, DateTimeOffset startTimeUtc)
   at Quartz.Core.JobRunShell.Run(CancellationToken cancellationToken)]
System.InvalidOperationException: Not a recovering job
   at Quartz.Impl.JobExecutionContextImpl.get_RecoveringTriggerKey()
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.PropertyFetch.RefTypedFetchProperty`2.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.PropertySpec.Fetch(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.TransformSpec.Morph(Object obj)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.Morph(Object args)
   at System.Diagnostics.DiagnosticSourceEventSource.FilterAndTransform.<>c__DisplayClass2_1.<.ctor>b__2(KeyValuePair`2 evnt)
   at System.Diagnostics.DiagnosticSourceEventSource.CallbackObserver`1.OnNext(T value)
   at System.Diagnostics.DiagnosticListener.Write(String name, Object value)
   at System.Diagnostics.DiagnosticSource.StartActivity(Activity activity, Object args)
   at Quartz.Logging.JobDiagnosticsWriter.WriteStarted(IJobExecutionContext context, DateTimeOffset startTimeUtc)
   at Quartz.Core.JobRunShell.Run(CancellationToken cancellationToken)
2021-05-05 09:11:24.3296 | DEBUG | Trigger instruction : NoInstruction 
2021-05-05 09:11:24.3361 | DEBUG | Batch acquisition of 1 triggers 

I've got the following execute-method in my MyJob.cs, where MyJob has [DisallowConcurrentExecution] set:

...
/// <summary>
        /// using quartz for periodic publishing.
        /// </summary>
        /// <param name="context">quartz' execution context.</param>
        public async Task Execute(IJobExecutionContext context)
        {
            try
            {
                _logger.LogDebug($"Execution of Periodic Task in {nameof(MyJob)}...");
                await Publish();
            }
            catch (Exception ex)
            {
                _logger.LogError(ex, $"Execution of Periodic Task in {nameof(MyJob)} failed!");

                // false => don't refire the event immediately
                throw new JobExecutionException("Exception in periodic Handling, skipping Tick.", ex, false);
            }
        }

So, to make a long story short: I have no clue why my exception handler does not handle the occuring exception when calling the Execute Method. It feels like this exception is hiding some underlying problem, but I can't debug it because locally I have no problem, execute just gets executed every x seconds. Or that something in the IJobExecutionContext throws the unhandled exception. Actually, this does not lead to a shutdown of my hostedservice, the exception is only thrown every interval.

Any help on why this exception is unhandled would be great!

To be honest I think I am doing something wrong or not getting some concept here ;)

Best regards,
Dominik
Version used

QUARTZ .net 3.3.2
Docker 19.03.6

Expected behavior
1) Execute fires normally without unhandled exception.
2) When an unhandled exception is thrown, it is handled by try/catch in execute.

Additional context
Add any other context about the problem here.

[lahma]

Thanks for the detailed report. Seems that this is a bug in trace writing, trace writer writes the context and there's a not-so-nice property that can throw in getter is called when context is not in state that the call is expected. Until this is properly fixed I think there should be a way to disable trace context for Quartz if you have somehow configured it to be used (activities, monitoring, maybe some logging).

Diagnostics listener is under name "Quartz".

[Pinguwien]

Thanks for your quick response. I am fairly new to Quartz.NET and Quartz in general, so could you please elaborate a little more on how to disable the trace context / diagnostics listener? I really have no more config than shown, apart from the AddJobAndTrigger convenience method which is the same as in Andrews article. Thanks in advance! :)

[lahma]

I'm sorry but I'll have time to dig deeper into this evening the earliest (no guarantees!), but you could try to clear other loggers at least in your ConfigureLogging:

ConfigureLogging(x => x.ClearProviders());

After that UseNLog should register only NLog...

[Pinguwien]

I am actually doing that right now. Here's the complete code of my BuildWebHost method:

public static IHostBuilder BuildWebHost(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                })
                .ConfigureLogging((hostingContext, logging) =>
                {
                    logging.ClearProviders();
                    logging.SetMinimumLevel(LogLevel.Trace);
                })
                .UseNLog()
                .ConfigureServices(
                    (hostContext, services) =>
                    {
                        services.AddHostedService<LifecycleOrchestrator>();

                        // Add the required Quartz.NET services
                        services.AddQuartz(quartzConfigurator =>
                        {
                            quartzConfigurator.SchedulerId = "my-scheduler";
                            quartzConfigurator.SchedulerName = "MyScheduler";
                            quartzConfigurator.UseDefaultThreadPool(options => options.MaxConcurrency = 3);

                            // tells Quartz.NET to register an IJobFactory that creates jobs for transient, scoped or singleton services
                            // by fetching them from the DI container.
                            quartzConfigurator.UseMicrosoftDependencyInjectionScopedJobFactory();
                            quartzConfigurator.AddJobAndTrigger<MyJob>(
                                hostContext.Configuration);
                        });

                        // Add the Quartz.NET hosted service
                        services.AddQuartzHostedService(
                            quartzOptions => quartzOptions.WaitForJobsToComplete = true);
                    });

so sadly that doesn't solve the problem. I'll check if I find it myself, though :) Thanks again!

[Pinguwien]

@lahma

Ok, i digged deeper and could nail it down.

Short context: I have two pipelines, both with deployment to same docker host. One pipeline deployment worked, the other not. So I did some diffs of my running docker containers docker inspect output, and to make a long story short:

As long as the following env vars for my container are not set, Quartz works perfectly:

$(echo --env COMPlus_PerfMapEnabled=1)
$(echo --env COMPlus_EnableEventLog=1)

see ms docs (e.g. here) for more info: https://docs.microsoft.com/en-us/dotnet/core/run-time-config/debugging-profiling

In one pipeline these are set, in the other they are not.

So after that I've tried it locally without docker by setting only
```
export COMPlus_EnableEventLog=1
````
followed by a dotnet run of my project, and what should I say: I was now able to reproduce the error locally, also. So this is most likely a Bug when using Quartz.NET and having the debugging flags of .net core enabled. :)

So as long as there's no bugfix I'll remove the env vars now from my pipeline for this dedicated container, I don't relly need them, they're just generally set for every containerized solution in the test env for debugging purposes. But I hope this might help you find the fix :)

edit: if you want, I can create another issue for this more specific and reproducable problem. ;)

[lahma]

Great to hear you found a workaround. Thanks for describing the setup, should help with the bug fix effort!