More log messages after moving to NServiceBus.Extensions.Logging

,
1

Hi,

I’m currently moving from NServiceBus.Log4Net 3.0 to NServiceBus.Extensions.Logging 1.0 with Microsoft.Extensions.Logging.Log4Net.AspNetCore 3.1 as suggested by the deprecation message.

The only code change I did/had to do is moving from

log4net.Config.XmlConfigurator.ConfigureAndWatch(
    log4net.LogManager.GetRepository(Assembly.GetEntryAssembly()),
    new FileInfo(Path.Combine(absoluteFolderPathOfExecutable, "log4net.config")));

LogManager.Use<Log4NetFactory>();

to this

var loggingOptions = new Log4NetProviderOptions(
    Path.Combine(absoluteFolderPathOfExecutable, "log4net.config"),
    true);

LogManager.UseFactory(
    new ExtensionsLoggerFactory(
        new LoggerFactory(new List<ILoggerProvider>() { new Log4NetProvider(loggingOptions) })));

BUT
using the simplest scenario to verify the logging still works (stop SQL Server that’s used as transport, run the endpoint and wait until the process kills itself).
I expect a lot of log messages, though I don’t understand why the amount I get with before and after are completely different:

Before:
I get 2x

2020-04-07 12:43:30,836 WARN NServiceBus.Transport.SQLServer.ExpiredMessagesPurger [(null)] Checking indexes on table [omitted] failed. Exception: System.Data.SqlClient.SqlException (0x80131904): A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
 ---> System.ComponentModel.Win32Exception (53): The network path was not found.`

and 1357x (which sounds like an incredibly large number of log messages)

2020-04-07 12:43:30,836 FATAL NServiceBus.Transport.SQLServer.DelayedMessageHandler [(null)] Exception thrown while performing cancellation
System.Data.SqlClient.SqlException (0x80131904): A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
 ---> System.ComponentModel.Win32Exception (53): The network path was not found.

After:
still 2x MessagesPurger
but 3738x the DelayedMessageHandler

My questions:

  1. is it normal to have such a large number of log messages when NServiceBus cannot connect to the SQL Server Transport? What part of the configuration has an impact on how often it tries?
  2. Is there a reasonable explanation to have vastly different numbers between the two different versions/packages?
  3. Is there anything wrong with the configuration change I made?

Though the remaining 2 MessagesPurger log messages make me pretty confident I didn’t mess up with the change I did.

Let me know if you need additional information to answer my questions.

Thank you
Philipp

2

Do you also see duplication of other log events?

3

For other things I only get as many as I’m used to.
e.g. 1 log message per delayed retry cycle.

So, the rest looks good.

4

I think that the error location is different because the logger is different. Maybe its just purely coincidental.

What versions of the core, transport and persistence are you running? Are you running the latest minor patch releases? Easiest way is to see if the package manager is showing any updates.

Also, do you have a critical error handler defined and if so could you share its implementation?

5

I think that the error location is different because the logger is different. Maybe its just purely coincidental.

I don’t quite understand what you mean with “different location”. It’s just the amount of messages in that startup scenario that is hugely different.

NServiceBus 7.2.3
NServiceBus.SqlServer 4.3.1
NServiceBus.Persistence.Sql 4.6.0

We’re currently planning to upgrade transport and persistence, just couldn’t do it during the critical time of the year for our business.

The critical error handler is

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

private static void FailFast(string message, Exception exception)
{
    try
    {
        Log.Fatal(message, exception);
        log4net.LogManager.Shutdown();
    }
    finally
    {
        Environment.FailFast(message, exception);
    }
}
6

The loggers are different as these errors happen at different locations:

NServiceBus.Transport.SQLServer.ExpiredMessagesPurger vs NServiceBus.Transport.SQLServer.DelayedMessageHandler

That implementation is 100% correct. It ensures FailFast is always invoked in the finally.

Based on the release notes you are not missing out on logging enhancements

However, in 4.3.1 there is a fix:

This looks like the behavior you are experiencing. Can you please that you are running 4.3.1 by checking the assembly info or viewing the diagnostics file.

7

The loggers are different as these errors happen at different locations:

Ah, got it.

Can you please that you are running 4.3.1

Assembly Product version in build output says: 4.3.0+0.Branch.release-4.3.Sha.9808911dc1a61b1795dbc39db3e77d6e06b0e155.9808911dc1a61b1795dbc39db3e77d6e06b0e155

The file in .diagnostics folder says:
"Transport":{"Type":"NServiceBus.SqlServerTransport","Version":"4.3.0"}}
and the assets.cache in the obj folder says
.nuget\packages\nservicebus.sqlserver\4.3.0\lib\netstandard2.0\NServiceBus.Transport.SqlServer.dll

The Nuget version in the solution said 4.3.1 but I figured out in the service it’s only referenced indirectly and therefore 4.3.0. I will make sure that it will be 4.3.1 and come back to you.

The .diagnostics also says

"NServiceBus.Transport.SqlServer.ExpiredMessagesPurger":{"FeatureEnabled":false,"BatchSize":null}

which makes me wonder why there are even any log messages related to the expired messages purger. Just an observation

8

After explicitly installing 4.3.1 in the service the logs look reasonable again when it fails on startup. No flooding as before.

Sorry for the confusion with the version numbers.
Thanks and happy easter

9

Thanks for the update and glad the log flooding is resolved.

That is indeed a little strange for a feature that is not enabled. I’ll create an issue for it for us to look at.

Thanks for reporting!

10

Issue on this small bug: ExpiredMessagesPurger initialized and connecting to storage even though it's disabled · Issue #610 · Particular/NServiceBus.SqlServer · GitHub

11

Hi Philipp

We have improved the diagnostics section, the logging and are making sure that the indexes are not checked when the expired message purger is disabled as part of 6.1.2.

Regards
Daniel