Quick Question on Net8 Windows Service and Message Handlers and Message Pump Stability

Hey folks looking for some quick advice here. In a small project for a friend we’ve seen a weird situation where the NSB message pump appears to just stop, no errors, no exceptions, no logs, but the app is still running and going fine otherwise and you can attach a debugger and the app’s timer based logic is going fine. Just that randomly we get a situation where messages simply don’t process in the queue. This situation is “Solved” with restarting the app and the message queue will drain. Details as follows:

So helping some folks on a net 8 base upgrade on a well baked stable Net Framework service that uses NSB. Normally this should be a quick deal (and at first, it appeared so). But we’ve noticed the queue issue noted above. Let me outline all the packages and moving parts and what I did.

So first of all this is windows 8 console app targeting windows (they’re a MS shop so fair enough) so using -Microsoft.Extensions.Hosting.WindowsServices 8.0 package as the base and the typical IHostBuilder.UseWindowsService() call followed by using -NServiceBus.Extensions.Hosting 2.0.1, again with the typical IHostBuilder.UserNServceBus() call. Nothing fancy or going off the reservation. This is fundamentally a very simple application.

Rest of the NSB related packages are
-NServiceBus 8.2.4
-NServiceBus.Newtonsoft.Json 3.0.1
-NServiceBus.Persistence.Sql 7.0.6
-NServiceBus.SqlServer 7.0.9

Other important bits are
-EntityFramework 6.5.1
-Microsoft.EntitytFramework.SqlServer 6.5.1

(If you ask “Why EF not EF Core”, mainly as I wanted to focus on migrating the host vs their internal handler/entity logic at the same time)

In the process I migrated handlers one or two at a time from “instance 1” to “instance 2” endpoint slowly strangling the old implementation until (hopefully) all that’s left is the new migrated application and the old Net Framework instance gets decommissioned.

So immediate things to note
Right as the app starts up were making sure we’ve opted in for DTC support as well as using the EF provider that uses Microsoft.Data.SqlCLient 6.0.1 so we got that covered

// Used to instruct Net8 that yes, we do want DTC
TransactionManager.ImplicitDistributedTransactions = true;

//Override to use new EF provider - must happen before any DB code
System.Data.Entity.DbConfiguration.SetConfiguration(new MicrosoftSqlDbConfiguration());

At first I figured “Oh we failed the log and restart the service on critical error” but I’ve made sure that they’re logging out failed messages and critical error action is set. I also extended this to support recovery logging events as well like this

// Recoverability settings
{
  var recoverability = endpointConfiguration.Recoverability();

  recoverability.Immediate(settings => settings.OnMessageBeingRetried((retry, ct) => 
    Logger.LogEventAsync(retry.Exception, Severity.Medium, $"Message {retry.MessageId} will be retried immediately.", ct)));

    recoverability.Delayed(settings => settings.OnMessageBeingRetried((retry, ct) => 
      Logger.LogEventAsync(retry.Exception, Severity.Medium, $"Message {retry.MessageId} will be retried after a delay.", ct)));

    recoverability.Failed(settings => settings.OnMessageSentToErrorQueue((failed, ct) => 
      Logger.LogEventAsync(failed.Exception, Severity.High, $"Message {failed.MessageId} will be sent to the error queue.", ct)));
                
      endpointConfiguration.DefineCriticalErrorAction(OnCriticalError);
      endpointConfiguration.Recoverability().Failed(s =>
       {
         s.OnMessageSentToErrorQueue(OnMessageSentToErrorQueue);
        });
}

The implementation of the OnCriticalError is

private static async Task OnCriticalError(ICriticalErrorContext context, CancellationToken cancellation)
 {
   if (Debugger.IsAttached) Debugger.Break();

   var exception = context.Exception;
   var errorMessage = context.Error;

   await Logger.LogEventAsync(exception, Severity.Fatal, $"Fatal Bus exception: {errorMessage}", cancellation);

   try
   {
     await context.Stop(cancellationToken).ConfigureAwait(false);
   }
   finally
   {
     Environment.FailFast(fatalMessage, context.Exception);
   }
}

Again, this is pretty standard stuff here.

We never see a log about failures. We never get errors into the log. Nothing. Just some number of messages process and suddenly, nothing.

I am 100% certain I am missing something but for the life of me I can’t see what. Any ideas?
Have I missed another bit of logging or tracing that could uncover what is going on here?

thanks in advance!

Let me add, in my attempts to figure out what may be going on I have added Serilog into the mix tracing out message and pipeline information into some rolling log files.

-Microsoft.Extensions.Logging 8.0.0
-Serilog 4.2.0
-Serilog.Extensions.Logging 8.0.0
-Serilog.Sinks.File 7.0.0

In addition, i’ve added a quick and dirty log to the top of every handler’s Handle() method like this

this.logger.CreateLogger<*MyHandler*>().LogInformation($"Handling message type: {message.GetType()} {context.MessageId}");

The idea being if I could see some commonality where “Message type XYZ is processed every time prior to the message pump dies”. Nothing so far.

The NSB logging outputs the following (nothing strikes me as unexpected)

2025-05-03 05:22:32.900 INFO Logging to ‘c:\Program FilesCrmService2\Logging’ with level Debug
2025-05-03 05:22:32.934 DEBUG Activating persistence ‘SqlPersistence’ to provide storage for ‘NServiceBus.StorageType+Outbox’ storage.
2025-05-03 05:22:32.938 DEBUG Activating persistence ‘SqlPersistence’ to provide storage for ‘NServiceBus.StorageType+Sagas’ storage.
2025-05-03 05:22:32.938 DEBUG Activating persistence ‘SqlPersistence’ to provide storage for ‘NServiceBus.StorageType+Subscriptions’ storage.
2025-05-03 05:22:32.957 DEBUG CrmService.MaxioIntegration.AccountAssignedEventHandler+UpdateAccountOwnerCommand identified as message type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:32.958 DEBUG CrmService.MaxioIntegration.SynchronizeNewClientsWithMaxioHandler+SynchronizeCommand identified as message type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:32.959 DEBUG CrmService.MaxioIntegration.UpdateCustomerContactDetailsHandler+SynchronizeCommand identified as message type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:32.959 DEBUG CrmService.MaxioIntegration.UpdateCustomerDetailsForClientsChangesHandler+SynchronizeCommand identified as message type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:32.959 DEBUG CrmService.HubSpotIntegration.AccountDetailsUpdatedHandler+UpdateHubSpotContactCommand identified as message type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:32.960 DEBUG CrmService.HubSpotIntegration.ContactSyncForAccountCreatedHandler+AssociateWithHubSpotCommand identified as message type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:33.008 DEBUG Number of messages found: 16
2025-05-03 05:22:33.012 DEBUG Message definitions:
CrmService.MaxioIntegration.UpdateCustomerContactDetailsHandler+SynchronizeCommand
CrmService.MaxioIntegration.AccountAssignedEventHandler+UpdateAccountOwnerCommand
CustomerManagement.Contracts.AccountContactsUpdatedEvent
CustomerManagement.Contracts.CreateClientAuditCommand
CustomerManagement.Contracts.DisableApiTrialCommand
CrmService.MaxioIntegration.UpdateCustomerDetailsForClientsChangesHandler+SynchronizeCommand
CustomerManagement.Contracts.ExtendApiTrialCommand
CustomerManagement.Contracts.AssignAccountCommand
CrmService.HubSpotIntegration.ContactSyncForAccountCreatedHandler+AssociateWithHubSpotCommand
CustomerManagement.Contracts.TrialIdentityCreatedEvent
CustomerManagement.Contracts.AccountCreatedEvent
CrmService.HubSpotIntegration.AccountDetailsUpdatedHandler+UpdateHubSpotContactCommand
CustomerManagement.Contracts.ManageSecurityRolesCommand
CustomerManagement.Contracts.AccountDetailsUpdatedEvent
CrmService.MaxioIntegration.SynchronizeNewClientsWithMaxioHandler+SynchronizeCommand
CustomerManagement.Contracts.AccountAssignedEvent
2025-05-03 05:22:33.037 DEBUG Looking for license in the following locations:
License not found in c:\Program FilesCrmService2\license.xml
License not found in C:\Users\crmserviceuser\AppData\Local\ParticularSoftware\license.xml
License not found in C:\ProgramData\ParticularSoftware\license.xml
License not found in Environment variable ‘PARTICULARSOFTWARE_LICENSE’
No valid license could be found. Falling back to trial license with start date ‘2025-04-20’.
2025-05-03 05:22:33.038 INFO No valid license could be found. Falling back to trial license with start date ‘2025-04-20’.
2025-05-03 05:22:33.051 DEBUG Error queue retrieved from code configuration via ‘EndpointConfiguration.SendFailedMessagesTo()’.
2025-05-03 05:22:33.059 DEBUG CustomerManagement.Contracts.AssignAccountCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.060 DEBUG CustomerManagement.Contracts.CorrelateFileCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.060 DEBUG CustomerManagement.Contracts.CreateClientAuditCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.061 DEBUG CustomerManagement.Contracts.DeleteAccountDocumentCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.061 DEBUG CustomerManagement.Contracts.DisableApiTrialCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.062 DEBUG CustomerManagement.Contracts.ExtendApiTrialCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.062 DEBUG CustomerManagement.Contracts.LeadPhilanthropySignupCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.063 DEBUG CustomerManagement.Contracts.ManageSecurityRolesCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.064 DEBUG CustomerManagement.Contracts.NationBuilderSignupCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.064 DEBUG CustomerManagement.Contracts.ProvisionExternalUserCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.064 DEBUG CustomerManagement.Contracts.RequestTrialLeadCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.065 DEBUG CustomerManagement.Contracts.ResendEmailCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.065 DEBUG CustomerManagement.Contracts.SalesDirectedSignupCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.066 DEBUG CustomerManagement.Contracts.SelfSignupCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.066 DEBUG CustomerManagement.Contracts.SendAccountEmailCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.066 DEBUG CustomerManagement.Contracts.StoreAccountDocumentCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.067 DEBUG CustomerManagement.Contracts.StoreAccountFileCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.067 DEBUG CustomerManagement.Contracts.UpdateAccountContactsCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.068 DEBUG CustomerManagement.Contracts.UpdateAccountPartyCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.068 DEBUG CustomerManagement.Contracts.UpdateFileCorrelationIdCommand identified as command type by CustomerManagement.Contracts but does not match message type convention. Treating as a message.
2025-05-03 05:22:33.071 DEBUG Error queue retrieved from code configuration via ‘EndpointConfiguration.SendFailedMessagesTo()’.
2025-05-03 05:22:33.089 DEBUG Associated ‘CustomerManagement.Contracts.AccountCreatedEvent’ message with ‘CrmService.AccountCreatedEventHandler’ handler.
2025-05-03 05:22:33.090 DEBUG Associated ‘CustomerManagement.Contracts.AccountAssignedEvent’ message with ‘CrmService.MaxioIntegration.AccountAssignedEventHandler’ handler.
2025-05-03 05:22:33.091 DEBUG Associated ‘CrmService.MaxioIntegration.AccountAssignedEventHandler+UpdateAccountOwnerCommand’ message with ‘CrmService.MaxioIntegration.AccountAssignedEventHandler’ handler.
2025-05-03 05:22:33.092 DEBUG Associated ‘CrmService.MaxioIntegration.SynchronizeNewClientsWithMaxioHandler+SynchronizeCommand’ message with ‘CrmService.MaxioIntegration.SynchronizeNewClientsWithMaxioHandler’ handler.
2025-05-03 05:22:33.092 DEBUG Associated ‘CrmService.MaxioIntegration.UpdateCustomerContactDetailsHandler+SynchronizeCommand’ message with ‘CrmService.MaxioIntegration.UpdateCustomerContactDetailsHandler’ handler.
2025-05-03 05:22:33.093 DEBUG Associated ‘CustomerManagement.Contracts.AccountContactsUpdatedEvent’ message with ‘CrmService.MaxioIntegration.UpdateCustomerContactDetailsHandler’ handler.
2025-05-03 05:22:33.093 DEBUG Associated ‘CustomerManagement.Contracts.AccountDetailsUpdatedEvent’ message with ‘CrmService.MaxioIntegration.UpdateCustomerDetailsForClientsChangesHandler’ handler.
2025-05-03 05:22:33.094 DEBUG Associated ‘CrmService.MaxioIntegration.UpdateCustomerDetailsForClientsChangesHandler+SynchronizeCommand’ message with ‘CrmService.MaxioIntegration.UpdateCustomerDetailsForClientsChangesHandler’ handler.
2025-05-03 05:22:33.095 DEBUG Associated ‘CustomerManagement.Contracts.AccountDetailsUpdatedEvent’ message with ‘CrmService.HubSpotIntegration.AccountDetailsUpdatedHandler’ handler.
2025-05-03 05:22:33.095 DEBUG Associated ‘CrmService.HubSpotIntegration.AccountDetailsUpdatedHandler+UpdateHubSpotContactCommand’ message with ‘CrmService.HubSpotIntegration.AccountDetailsUpdatedHandler’ handler.
2025-05-03 05:22:33.096 DEBUG Associated ‘CrmService.HubSpotIntegration.ContactSyncForAccountCreatedHandler+AssociateWithHubSpotCommand’ message with ‘CrmService.HubSpotIntegration.ContactSyncForAccountCreatedHandler’ handler.
2025-05-03 05:22:33.096 DEBUG Associated ‘CustomerManagement.Contracts.TrialIdentityCreatedEvent’ message with ‘CrmService.HubSpotIntegration.LeadSyncForApiTrialHandler’ handler.
2025-05-03 05:22:33.097 DEBUG Associated ‘CustomerManagement.Contracts.AssignAccountCommand’ message with ‘CustomerManagement.Handlers.AssignAccountHandler’ handler.
2025-05-03 05:22:33.097 DEBUG Associated ‘CustomerManagement.Contracts.CreateClientAuditCommand’ message with ‘CustomerManagement.Handlers.CreateAuditCommandHandler’ handler.
2025-05-03 05:22:33.098 DEBUG Associated ‘CustomerManagement.Contracts.DisableApiTrialCommand’ message with ‘CustomerManagement.Handlers.DisableApiTrialCommandHandler’ handler.
2025-05-03 05:22:33.099 DEBUG Associated ‘CustomerManagement.Contracts.ExtendApiTrialCommand’ message with ‘CustomerManagement.Handlers.ExtendApiTrialCommandHandler’ handler.
2025-05-03 05:22:33.099 DEBUG Associated ‘CustomerManagement.Contracts.ManageSecurityRolesCommand’ message with ‘CustomerManagement.Handlers.ManageSecurityCommandHandler’ handler.
2025-05-03 05:22:34.671 DEBUG CustomerManagement.Contracts.AccountCreatedEvent identified as event type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.672 DEBUG CustomerManagement.Contracts.AccountAssignedEvent identified as event type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.672 DEBUG CrmService.MaxioIntegration.AccountAssignedEventHandler+UpdateAccountOwnerCommand identified as command type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:34.673 DEBUG CrmService.MaxioIntegration.SynchronizeNewClientsWithMaxioHandler+SynchronizeCommand identified as command type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:34.673 DEBUG CrmService.MaxioIntegration.UpdateCustomerContactDetailsHandler+SynchronizeCommand identified as command type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:34.674 DEBUG CustomerManagement.Contracts.AccountContactsUpdatedEvent identified as event type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.674 DEBUG CustomerManagement.Contracts.AccountDetailsUpdatedEvent identified as event type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.675 DEBUG CrmService.MaxioIntegration.UpdateCustomerDetailsForClientsChangesHandler+SynchronizeCommand identified as command type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:34.675 DEBUG CrmService.HubSpotIntegration.AccountDetailsUpdatedHandler+UpdateHubSpotContactCommand identified as command type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:34.675 DEBUG CrmService.HubSpotIntegration.ContactSyncForAccountCreatedHandler+AssociateWithHubSpotCommand identified as command type by NServiceBus Marker Interfaces convention.
2025-05-03 05:22:34.676 DEBUG CustomerManagement.Contracts.TrialIdentityCreatedEvent identified as event type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.676 DEBUG CustomerManagement.Contracts.AssignAccountCommand identified as command type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.677 DEBUG CustomerManagement.Contracts.CreateClientAuditCommand identified as command type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.677 DEBUG CustomerManagement.Contracts.DisableApiTrialCommand identified as command type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.678 DEBUG CustomerManagement.Contracts.ExtendApiTrialCommand identified as command type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.678 DEBUG CustomerManagement.Contracts.ManageSecurityRolesCommand identified as command type by CustomerManagement.Contracts convention.
2025-05-03 05:22:34.707 DEBUG Receiver Main is starting.
2025-05-03 06:46:51.054 DEBUG Stopping Main receiver

Likewise here’s the message handler logs for the last time she just stopped running

2025-05-03 06:51:00.437 -07:00 [INF] Application started.
2025-05-03 06:51:00.509 -07:00 [WRN] Maximum connection pooling value (Max Pool Size=N) is not configured on the provided connection string. The default value (100) will be used.
2025-05-03 06:51:01.740 -07:00 [WRN] Table CRM2@[bus]@[SharedDB] does not contain non-clustered index for column ‘RowVersion’.
Migrating to this non-clustered index improves performance for send and receive operations.
2025-05-03 06:51:02.825 -07:00 [INF] Service starting…
2025-05-03 06:51:02.826 -07:00 [INF] Service is running…
2025-05-03 06:51:02.902 -07:00 [INF] Application started. Hosting environment: Production; Content root path: c:\Program Files\CrmService2
2025-05-03 06:51:03.501 -07:00 [INF] Handling message type: CrmService.MaxioIntegration.SynchronizeNewClientsWithMaxioHandler+SynchronizeCommand d83c29c9-6c86-43b7-9b01-b2d200e34053
2025-05-03 06:51:06.329 -07:00 [INF] Handling message type: CrmService.MaxioIntegration.SynchronizeNewClientsWithMaxioHandler+SynchronizeCommand 48ff8d15-b050-430e-9e3c-b2d200e34048
2025-05-03 06:52:52.216 -07:00 [INF] Application is shutting down…
2025-05-03 06:52:52.219 -07:00 [INF] Service stopping…
2025-05-03 06:52:52.356 -07:00 [INF] Initiating shutdown.
2025-05-03 06:53:22.215 -07:00 [INF] Aborting graceful shutdown.

Hi Jimmy,

There is a lot in your logs and settings which makes it harder to distill the actual issue. Can you provide a minimal code that reproduces the issue? I imagine that may be helpful for people trying to assist you.

Regarding your configuration code:

  • It seems like you configure OnMessageSentToErrorQueue twice which may not work as you expected (one call will override the other). Can this be simplified/
  • You showed that you configure s.OnMessageSentToErrorQueue(OnMessageSentToErrorQueue); but I don’t see the code of the delegate OnMessageSentToErrorQueue that you pass as an argument. Can you attach this method?
  • I don’t think you need to configure logging on Immediate. The logging is there out of the box

You mention that you randomly get into a situation where messages are not processed:

  • Is it truly “randomly” or do you see some pattern there? Could be timing, could be some specific message causing it, could be memory usage.
  • Can you capture a memory dump of the process once you see it not processing the messages anymore? You could then analyze the memory dump and see if there are any deadlocks or hanging threads/tasks.

Cheers,
Adam Furmanek

Thanks for checking back.
Yes it truly seems to be a random situation. I’ve been logging messages and types into logs and we can see every type of message we handle at some point being the last thing processed. Likewise we can see messages spanning the whole set process, sometimes for hours/days and then randomly poof!

But you will be glad to know that I finally tracked this down but it’s very very strange that the system would behave this way. After stepping away for a bit I went through the code with fresh eyes and noticed both the nservicebus.transport.sqlserver and the nservicebus.sqlserver packages had been added to the project, the latter as a dependency of another package they used. Once we pulled this and corrected a using statement everything sorted itself out.

Very odd that the message pump behaved that way without emitting critical failure events but it is what it is. Hopefully if someone else bumps into this they will find this post and be able to double check their own indirect dependencies!

appreciate the assist!