hangfire-postgres / Hangfire.PostgreSql

PostgreSql Storage Provider for Hangfire
Other
358 stars 132 forks source link

TransactionScope enlistment regression in 1.20.2 #331

Closed KernelCrap closed 11 months ago

KernelCrap commented 11 months ago

Enqueuing a job inside a transaction scope no longer runs as expected after updating from 1.20.1 to 1.20.2.

It might be related to the following change: Fixing Enqueued Job Trigger for Multiple Queues

Runnable example code:

using Hangfire;
using Hangfire.PostgreSql;

using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;

using System.Transactions;

var host = new HostBuilder()
    .ConfigureServices((context, services) =>
    {
        const string ConnectionString = "Host=localhost;Port=5432;Database=test;Username=postgres";

        services.AddDbContext<TestContext>(optionsBuilder 
            => optionsBuilder.UseNpgsql(ConnectionString));

        var options = new PostgreSqlStorageOptions
        {
            EnableTransactionScopeEnlistment = true
        };

        services.AddHangfire((provider, config)
            => config.UsePostgreSqlStorage(ConnectionString, options));

        services.AddHangfireServer();
        services.AddTransient<ItemAddJob>();
    })
    .Build();

using (var scope = host.Services.CreateScope())
{
    var context = scope.ServiceProvider
        .GetRequiredService<TestContext>();

    await context.Database.EnsureDeletedAsync();
    await context.Database.EnsureCreatedAsync();
}

await host.StartAsync();

using (var scope = host.Services.CreateScope())
{
    var context = scope.ServiceProvider
        .GetRequiredService<TestContext>();

    var options = new TransactionOptions
    {
        IsolationLevel = IsolationLevel.Serializable
    };

    using (var ts = new TransactionScope(
        TransactionScopeOption.Required, options, TransactionScopeAsyncFlowOption.Enabled))
    {
        Console.WriteLine($"[{DateTime.UtcNow:O}]: TransactionScope: Started");

        context.Items.Add(new Item(1, "A"));

        await context.SaveChangesAsync();

        BackgroundJob.Enqueue<ItemAddJob>(e => e.Add(2, "B"));
        BackgroundJob.Enqueue<ItemAddJob>(e => e.Add(3, "B"));

        await context.SaveChangesAsync();

        ts.Complete();

        Console.WriteLine($"[{DateTime.UtcNow:O}]: TransactionScope: Completed");
    }

    Console.WriteLine($"[{DateTime.UtcNow:O}]: TransactionScope: Disposed. Waiting 5 seconds...");

    await Task.Delay(5000);

    var items = await context.Items.ToArrayAsync();

    Console.WriteLine($"[{DateTime.UtcNow:O}]: Items:");

    foreach (var item in items)
        Console.WriteLine($" - Item: {item.Id} - {item.Value}");

    await host.WaitForShutdownAsync();
}

public class ItemAddJob
{
    private readonly TestContext _context;

    public ItemAddJob(TestContext context)
    {
        _context = context;
    }

    public async Task Add(int id, string value)
    {
        Console.WriteLine($"[{DateTime.UtcNow:O}]: Hangfire task: Started #{id}");

        _context.Add(new Item(id, value));

        await _context.SaveChangesAsync();

        Console.WriteLine($"[{DateTime.UtcNow:O}]: Hangfire task: Completed #{id}");
    }
}

public class TestContext : DbContext
{
    public TestContext(DbContextOptions<TestContext> options) : base(options) { }
    public DbSet<Item> Items => Set<Item>();
}

public record Item(int Id, string Value);

Output with Hangfire.PostgreSql 1.20.2:

[2023-10-18T11:14:25.9833839Z]: TransactionScope: Started
[2023-10-18T11:14:26.6804603Z]: TransactionScope: Completed
[2023-10-18T11:14:26.6836808Z]: TransactionScope: Disposed. Waiting 5 seconds...
[2023-10-18T11:14:31.8639173Z]: Items:
 - Item: 1 - A
[2023-10-18T11:14:41.7238726Z]: Hangfire task: Started #3
[2023-10-18T11:14:41.7239170Z]: Hangfire task: Started #2
[2023-10-18T11:14:41.7723883Z]: Hangfire task: Completed #2
[2023-10-18T11:14:41.7754600Z]: Hangfire task: Completed #3

Output with Hangfire.PostgreSql 1.20.1 (runs as expected):

[2023-10-18T11:15:08.8346271Z]: TransactionScope: Started
[2023-10-18T11:15:09.4545437Z]: TransactionScope: Completed
[2023-10-18T11:15:09.4590676Z]: TransactionScope: Disposed. Waiting 5 seconds...
[2023-10-18T11:15:09.5326520Z]: Hangfire task: Started #3
[2023-10-18T11:15:09.5326558Z]: Hangfire task: Started #2
[2023-10-18T11:15:09.5794835Z]: Hangfire task: Completed #3
[2023-10-18T11:15:09.5794860Z]: Hangfire task: Completed #2
[2023-10-18T11:15:14.6145290Z]: Items:
 - Item: 1 - A
 - Item: 2 - B
 - Item: 3 - B
Tinyakov commented 11 months ago

I didn't dig deep yet, but it appears that the issue is in version 1.20.2 and it's my fault. There is no signal of new jobs after the transaction has been committed.

Tinyakov commented 11 months ago

I've made draft PR https://github.com/hangfire-postgres/Hangfire.PostgreSql/pull/332

The example code runs as expected, jobs execute immediately.

[2023-10-18T12:42:06.9614230Z]: TransactionScope: Started
[2023-10-18T12:42:07.1539390Z]: TransactionScope: Completed
[2023-10-18T12:42:07.1576300Z]: TransactionScope: Disposed. Waiting 5 seconds...
[2023-10-18T12:42:07.2001600Z]: Hangfire task: Started #3
[2023-10-18T12:42:07.2001970Z]: Hangfire task: Started #2
[2023-10-18T12:42:07.2246870Z]: Hangfire task: Completed #3
[2023-10-18T12:42:07.2246890Z]: Hangfire task: Completed #2
[2023-10-18T12:42:12.2758860Z]: Items:
 - Item: 1 - A
 - Item: 3 - B
 - Item: 2 - B

I haven't checked it properly yet, unfortunately I don't have time right now. If someone could check, I would appreciate it. Sorry for bug.

azygis commented 11 months ago

I don't think there's anything else to check. Code looks fine, tests are green, your own test shows the expected behavior like it was before the issue started.

Unless you have some extra stuff planned for your draft, I'd say we merge it and publish.

Tinyakov commented 11 months ago

I will check the case with several workers now, because of which I initially made the changes.

Tinyakov commented 11 months ago

@azygis , quick tests in my multi-worker, multi-queue environment were successful as well: jobs executed immediately, and the count of fetching queries did not increase.

I've removed the Draft label.

azygis commented 11 months ago

@Tinyakov thanks for super quick resolution!