SQL commands looping after start

[dannythunder]

Describe the bug Applicaion running Wolverine and Marten together, when I start the application SQL-commands keep on excecuting at logging inf-level. There s a lot of queries to the database.

To Reproduce Steps to reproduce the behavior:

1. Upgrading from previous major release to latest (see nugets below)
2. Start upp the application (tried on more than two existing applications, one with no DB at start, others had DB)

Expected behavior Not having SQL-commands running in a loop. Not spamming the log with inf-level logs.

Information: .net8 web api

<PackageReference Include="Marten" Version="7.16.0"/>
<PackageReference Include="WolverineFx.Marten" Version="2.9.0" />
<PackageReference Include="WolverineFx.RabbitMQ" Version="2.9.0" />

Settings:

Marten:

builder.Services.AddMarten(options =>
        {
            options.Connection(connectionString);
            options.DatabaseSchemaName = "servicenamn";

            // Sätt soft delete
            options.Schema.For<Issue>().Index(x => x.Id, indexConfig =>
            {
                indexConfig.IsUnique = true;
            }).SoftDeleted();

            // Domänevent
            options.Events.MetadataConfig.CorrelationIdEnabled = true;
            options.Events.AddEventType<IssueAddedDomainEvent>();

            options.CreateDatabasesForTenants(c =>
            {
                c.ForTenant()
                    .CheckAgainstPgDatabase()
                    .WithOwner("postgres")
                    .WithEncoding("UTF-8")
                    .ConnectionLimit(-1)
                    .OnDatabaseCreated(_ => { Console.WriteLine("Successfully created the database!"); });
            });
            options.GeneratedCodeMode = TypeLoadMode.Dynamic;
            options.AutoCreateSchemaObjects = AutoCreate.CreateOrUpdate;
        })
        .IntegrateWithWolverine()
        .UseLightweightSessions()
        .ApplyAllDatabaseChangesOnStartup();

        return builder;

Wolverine:

builder.Host.UseWolverine((context, opts) =>
        {
            opts.Policies
            .AllLocalQueues(x =>
            {
                x.MaximumParallelMessages(10);
                x.UseDurableInbox();
            });

            opts.Policies.AutoApplyTransactions();

            opts.OnException<CustomException>()
                .RetryWithCooldown(1.Seconds(), 5.Seconds(), 30.Seconds())
                .Then.MoveToErrorQueue();

            opts.Policies.UseDurableLocalQueues();
            opts.Policies.UseDurableInboxOnAllListeners();
            opts.Policies.UseDurableOutboxOnAllSendingEndpoints();
            opts.Discovery.IncludeAssembly(typeof(ApplicationAssembly).Assembly);
            opts.EnableLogAndTrace<CommandBase>();

            var queueName = typeof(ApplicationQueue).Namespace;

            opts.UseRabbitMq(c => { c.Uri = new Uri(connectionString); })
                .AutoProvision();

            opts.AddEventForExternalTopicPublishing(typeof(IssueCreatedEvent));

            opts.ListenToRabbitQueue(queueName, q =>
                {
                    q.PurgeOnStartup = false;
                    q.TimeToLive(5.Minutes());
                })
                .DeadLetterQueueing(new DeadLetterQueue($"{queueName}-deadletter"));
            SetOptionsForHandlers(opts);

            if (context.HostingEnvironment.IsDevelopment())
            {
                opts.Durability.Mode = DurabilityMode.Solo;
            }

            opts.UseSystemTextJsonForSerialization(stj =>
            {
                stj.UnknownTypeHandling = JsonUnknownTypeHandling.JsonNode;
            });

            opts.LocalQueueFor<CreateIssueCommandHandler>()
            .Sequential()
            .CircuitBreaker(cb =>
            {
                cb.PauseTime = 1.Minutes();
                cb.SamplingPeriod = 2.Minutes();
                cb.FailurePercentageThreshold = 20;
                cb.Include<TimeoutException>();
            });

            return opts;
        });

Output: Short version

[13:41:27 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:41:27 INF] Command execution completed (duration=23ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:41:27 INF] Command execution completed (duration=2ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:41:27 INF] Command execution completed (duration=2ms): select node_number from exampleservice.wolverine_nodes
[13:41:27 INF] Batch execution completed (duration=2ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:41:32 INF] Command execution completed (duration=9ms): SELECT pg_try_advisory_xact_lock($1)
[13:41:32 INF] Command execution completed (duration=50ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:41:32 INF] Command execution completed (duration=2ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:41:32 INF] Command execution completed (duration=24ms): select node_number from exampleservice.wolverine_nodes
[13:41:32 INF] Batch execution completed (duration=3ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:41:37 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:41:37 INF] Command execution completed (duration=94ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:41:37 INF] Command execution completed (duration=2ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:41:37 INF] Command execution completed (duration=27ms): select node_number from exampleservice.wolverine_nodes
[13:41:37 INF] Batch execution completed (duration=3ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:41:42 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:41:42 INF] Command execution completed (duration=67ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:41:42 INF] Command execution completed (duration=2ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:41:42 INF] Command execution completed (duration=24ms): select node_number from exampleservice.wolverine_nodes
[13:41:42 INF] Batch execution completed (duration=46ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:41:47 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:41:47 INF] Command execution completed (duration=116ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:41:47 INF] Command execution completed (duration=50ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:41:47 INF] Command execution completed (duration=50ms): select node_number from exampleservice.wolverine_nodes
[13:41:47 INF] Batch execution completed (duration=23ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:41:52 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:41:52 INF] Command execution completed (duration=47ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:41:52 INF] Command execution completed (duration=2ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:41:52 INF] Command execution completed (duration=44ms): select node_number from exampleservice.wolverine_nodes
[13:41:52 INF] Batch execution completed (duration=2ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:41:57 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:41:57 INF] Command execution completed (duration=23ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:41:57 INF] Command execution completed (duration=2ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:41:57 INF] Command execution completed (duration=25ms): select node_number from exampleservice.wolverine_nodes
[13:41:57 INF] Batch execution completed (duration=2ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:42:02 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:42:02 INF] Command execution completed (duration=70ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:42:02 INF] Command execution completed (duration=2ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:42:02 INF] Command execution completed (duration=2ms): select node_number from exampleservice.wolverine_nodes
[13:42:02 INF] Batch execution completed (duration=2ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:42:07 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:42:07 INF] Command execution completed (duration=23ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:42:07 INF] Command execution completed (duration=2ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:42:07 INF] Command execution completed (duration=26ms): select node_number from exampleservice.wolverine_nodes
[13:42:07 INF] Batch execution completed (duration=2ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]
[13:42:12 INF] Command execution completed (duration=2ms): SELECT pg_try_advisory_xact_lock($1)
[13:42:12 INF] Command execution completed (duration=24ms): select body, id, status, owner_id, execution_time, attempts, message_type, received_at from exampleservice.wolverine_incoming_envelopes where status = 'Scheduled' and execution_time <= $1 order by execution_time LIMIT 100
[13:42:12 INF] Command execution completed (duration=3ms): select distinct owner_id from exampleservice.wolverine_incoming_envelopes where owner_id > 0 union select distinct owner_id from exampleservice.wolverine_outgoing_envelopes where owner_id > 0
[13:42:12 INF] Command execution completed (duration=46ms): select node_number from exampleservice.wolverine_nodes
[13:42:12 INF] Batch execution completed (duration=2ms): ["select received_at, count(*) from exampleservice.wolverine_incoming_envelopes where status = 'Incoming' and owner_id = 0 group by received_at", "select distinct destination from exampleservice.wolverine_outgoing_envelopes where owner_id = 0", "delete from exampleservice.wolverine_incoming_envelopes where status = 'Handled' and keep_until <= $1", "insert into exampleservice.wolverine_incoming_envelopes (body, id, status, owner_id, execution_time, attempts, message_type, received_at) select body, id, 'Incoming', 0, null, 0, message_type, received_at from exampleservice.wolverine_dead_letters where replayable = $1", "delete from exampleservice.wolverine_dead_letters where replayable = $1"]

Hopefully this is enough information

[jeremydmiller]

@dannythunder That's a very complete issue, and every possible thing I would need to tell you that that's perfectly normal behavior. You can certainly disable the raw Npgsql logging that's absurdly noisy from Marten with StoreOptions.DisableNpgsqlLogging = true, or set up filters on ILogger. Or if you really care, configure both Marten & Wolverine to slow down the various polling.

[jeremydmiller]

Closing as there's nothing actionable from the Wolverine side.