MSMQ Endpoint using windows Generic Host fails to start

I recently started upgrading to NServiceBus 7.4 and in doing so changed my first upgrade project to use Windows Generic hosting. (We used to use NserviceBus Host) It runs fine on my windows 10 development machine, and runs fine as a service on my machine, but when I install it on a Windows 2012R2 server, it fails to start with nothing in the event log other than. “The service did not respond to the start or control request in a timely fashion.” in the system event log. The application event log has nothing.

Other pertinent info:

  1. Other endpoints using version 5 on MSMQ with NServiceBus host are running fine on this server.
  2. Program is dotNet framework 4.8
  3. I’ve managed to determine that the program doesn’t seem to get past the .Build() phase of CreateHostBuilder()

What I have tried so far:

  1. Ran the enpoint from the command line - works fine
  2. Changed the service user to be my adminstrative user
  3. Checked that all queues exist
  4. Added full permissions on queues in MSMQ
  5. Checked that user is a member of “Performance Log Users” and “Performance Monitor Users”
  6. Checked that user has “Log on as a service” right
  7. Installed net 4.8 framework on the server (in case some component was missing)
  8. Switch on dotnet fusion logging to see if any assmebly loads are failing - seems these are fine.
  9. Created a brand new simple test program - also fails (works fine from command prompt though)
  10. Checked that simple test program runs as a service on my development machine (runs fine)

My biggest frustration is that there are no error messages, no crash dump, nothing I can use to figure out what is wrong! (I put try … catch blocks around everything at one stage but none of the catch blocks trigger.)

My test program source:

namespace CrmBus.DataVault
{
    static class Program
    {
        public static void Main(string[] args)
        {
            CreateHostBuilder(args).Build().Run();
        }

        static IHostBuilder CreateHostBuilder(string[] args)
        {
            return Host.CreateDefaultBuilder(args)
                .UseWindowsService()
                .ConfigureLogging(logging =>
                {
                    logging.AddEventLog();
                })
                .UseNServiceBus(ctx =>
                {
                    // TODO: give the endpoint an appropriate name
                    var endpointConfiguration = new EndpointConfiguration("CrmBus.DataVault.Test");

                    // TODO: ensure the most appropriate serializer is chosen
                    // https://docs.particular.net/nservicebus/serialization/
                    endpointConfiguration.UseSerialization<NewtonsoftSerializer>();

                    endpointConfiguration.DefineCriticalErrorAction(OnCriticalError);

                    var transport = endpointConfiguration.UseTransport<MsmqTransport>();
                    endpointConfiguration.SendFailedMessagesTo("error");
                    endpointConfiguration.DisableFeature<TimeoutManager>();
                    transport.DisablePublishing();

                    return endpointConfiguration;
                });
        }

        static async Task OnCriticalError(ICriticalErrorContext context)
        {
            // TODO: decide if stopping the endpoint and exiting the process is the best response to a critical error
            // https://docs.particular.net/nservicebus/hosting/critical-errors
            // and consider setting up service recovery
            // https://docs.particular.net/nservicebus/hosting/windows-service#installation-restart-recovery
            try
            {
                await context.Stop();
            }
            finally
            {
                FailFast($"Critical error, shutting down: {context.Error}", context.Exception);
            }
        }

        static void FailFast(string message, Exception exception)
        {
            try
            {
                // TODO: decide what kind of last resort logging is necessary
                // TODO: when using an external logging framework it is important to flush any pending entries prior to calling FailFast
                // https://docs.particular.net/nservicebus/hosting/critical-errors#when-to-override-the-default-critical-error-action
            }
            finally
            {
                Environment.FailFast(message, exception);
            }
        }
    }
}

Since it doesn’t start properly my hunch is that something hangs either during config or during start. Can you add some log statements before calling CreateHostBuilder(args).Build() and then Run and perhaps also inside UseNServiceBus to see where it gets stuck?

Perhaps also dial up the loglevels https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-3.1#configure-logging ?

Are you using the latest version of https://docs.particular.net/nservicebus/hosting/extensions-hosting? (since it has better integration with MS logging)

Thanks for you input.

I had logging in my full application which included logging for every step in my custom configuration for the endpoint. When I ran that, I got logs up to the end of the configuration of the endpoint, and one after that which showed that the endpoint had configured its logging duruing startup, but nothing after that.

I will configure logging for this sample app also though, and check my nuget versions, then revert with my results.

Okay, I have added logging to the application, and confirmed that all nugets are latest:

Here is my project file:

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net48</TargetFramework>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.Hosting.Abstractions" Version="3.1.9" />
    <PackageReference Include="Microsoft.Extensions.Hosting.WindowsServices" Version="3.1.9" />
    <PackageReference Include="NServiceBus" Version="7.4.3" />
    <PackageReference Include="NServiceBus.Extensions.Hosting" Version="1.1.0" />
    <PackageReference Include="NServiceBus.Newtonsoft.Json" Version="2.2.0" />
    <PackageReference Include="NServiceBus.Transport.Msmq" Version="1.1.0" />
  </ItemGroup>

</Project>

Here is the source with logging:

using System;
using System.Diagnostics;
using System.Threading.Tasks;
using Microsoft.Extensions.Hosting;
using NServiceBus;
using Microsoft.Extensions.Logging;
using NServiceBus.Features;

namespace CrmBus.DataVault
{
    static class Program
    {
        public static async Task Main(string[] args)
        {
            using (var loggerFactory = LoggerFactory.Create(builder =>
            {
                builder.SetMinimumLevel(LogLevel.Information);
                builder.AddEventLog();
            }))
            {
                var logger = loggerFactory.CreateLogger("Main");
                logger.LogInformation("Creating host builder");
                var builder = CreateHostBuilder(args, loggerFactory);

                try
                {
                    logger.LogInformation("Building host");
                    var host = builder.Build();

                    logger.LogInformation("Running host");
                    await host.RunAsync();
                }
                catch (Exception ex)
                {
                    logger.LogError(ex, "Exception during host build/run");
                }
            }
        }

        static IHostBuilder CreateHostBuilder(string[] args, ILoggerFactory loggerFactory)
        {
            return Host.CreateDefaultBuilder(args)
                .UseWindowsService()
                .ConfigureLogging(logging =>
                {
                    logging.AddEventLog();
                })
                .UseNServiceBus(ctx =>
                {
                    var log = loggerFactory.CreateLogger("UseNServiceBus");
                    log.LogInformation("Creating config");
                    var endpointConfiguration = new EndpointConfiguration("CrmBus.DataVault");

                    log.LogInformation("Setting Critical error handler");
                    endpointConfiguration.DefineCriticalErrorAction(OnCriticalError);

                    log.LogInformation("Setting serializer");
                    endpointConfiguration.UseSerialization<NewtonsoftSerializer>();

                    log.LogInformation("Setting transport to MSMQ");
                    var transport = endpointConfiguration.UseTransport<MsmqTransport>();
                    endpointConfiguration.SendFailedMessagesTo("error");
                    endpointConfiguration.DisableFeature<TimeoutManager>();
                    transport.DisablePublishing();

                    log.LogInformation("Returning configuration");
                    return endpointConfiguration;
                });
        }

        static async Task OnCriticalError(ICriticalErrorContext context)
        {
            try
            {
                await context.Stop();
            }
            finally
            {
                FailFast($"Critical error, shutting down: {context.Error}", context.Exception);
            }
        }

        static void FailFast(string message, Exception exception)
        {
            Environment.FailFast(message, exception);
        }
    }
}

The event log shows the “Building host” entry, and then all the UseNServiceBus entries, the last one being “Returning configuration”. Nothing else is logged after this.

Ok so to summarize

  • UseNServiceBus() completes
  • Something in var host = builder.Build(); hangs

Right?

Just to make sure it’s NServiceBus that fails can you comment out .UseNServiceBus() and make sure that it works?

Yes, that’s correct. If I comment out UseNServiceBus() it works.

Another point: If I use the learning transport, it’s also fine. The moment I use MSMQ it hangs.

Okay, I have managed to get my service running by reverting to NServiceBus.Transport.MSMQ 1.0.0.

I built NServiceBus source into my test solution and added logging to most of the initialization code, and I finally arrived on the section (In msmqTransport.cs):

    log.Info($"MsmqTransport.ValidateIfDtcIsAvailable TransactionMode: {transactionMode}");
    using (var ts = new TransactionScope())
    {
        log.Info($"Transaction Info: {Transaction.Current.TransactionInformation.CreationTime} | {Transaction.Current.TransactionInformation.DistributedIdentifier} | {Transaction.Current.TransactionInformation.LocalIdentifier} | {Transaction.Current.TransactionInformation.Status}");
        log.Info("MsmqTransport.ValidateIfDtcIsAvailable TransactionInterop.GetTransmitterPropagationToken(Transaction.Current)");
        TransactionInterop.GetTransmitterPropagationToken(Transaction.Current); // Enforce promotion to MSDTC
        log.Info("MsmqTransport.ValidateIfDtcIsAvailable ts.Complete()");
        ts.Complete();
    }

The line “TransactionInterop.GetTransmitterPropagationToken(Transaction.Current);” causes the hang. I notice that this section is not included in NServiceBus.Transport.MSMQ 1.0.0, so I tried reverting and it works.

It’s possible that our dev server has a somehow broken MSDTC, but I don’t have access to try this on another server, so I’ll go with the solution that works!

We will in any case upgrade the servers sometime soon, and most probably move off MSMQ quite soon anyway.

If this post helps anyone else, I’m happy…

@StephenBethke can you be a bit more clear on what “it works” means? Are you doing any storage transactions? Very often MSMQ in combination with SQL requires distributed transactions so wondering if “it works” included usage of MSDTC.

Have you tried lowering the transaction mode of the transport?

transport.Transactions(TransportTransactionMode.SendsAtomicWithReceive);

Of course, this would only make sense if indeed you don’t require MSDTC.

Regards
Daniel

We do need MSDTC, and it’s a good point you raise - I didn’t test for message processing - I was so relieved just to see the service start.

I’ve just tried to send through a message but my new endpoint is failing to deserialize - seems our other endpoints are using XML.

As soon as I’ve sorted that out, I’ll send a message through and see if it processes right through.

@ramonsmits, the endpoint appears to be processing messages correctly. Our older endpoints which use transactions also seem to be working properly on this server.

Would the older endpoints (using NServiceBus.Host.exe) just silently process without MSDTC transactions if they were not available, or would they report errors?