[CRITICAL BUG] Messages are "rolled back" with the main transaction (simple TransactionScope)

[hidegh]

Never noticed before, but testing is simple.
We just need a job, 1 transaction scope that commits, and 1 that rolls back.

Issues:

• Logged message to the console disappears (also rolls back) in case of the 2nd transaction.
• Also until TX is committed, no logs are showing!

Expected behavior:

• Logging should be independent (separate transaction or outside transactions).
• Log messages showing up immediately (not just when TX commits)
• Log messages staying even when/after the TX rollbacks

Using:

• Hangfire Console 1.4.3 (and Hangfire Console Extensions)
• Local MS SQL 2022
• .NET 8, EF Core

This is the code inside the Job:

        jobProgress.WriteProgressLine(LogLevel.Information, "Before tran #1");
        using (var ts = TransactionScopeBuilder.New())
        {
            jobProgress.WriteProgressLine(LogLevel.Information, "Inside tran with commit");
            ts.Complete();
        }
        jobProgress.WriteProgressLine(LogLevel.Information, "After tran #1");

        jobProgress.WriteProgressLine(LogLevel.Information, "Before tran #2");
        using (var ts = TransactionScopeBuilder.New())
        {
            jobProgress.WriteProgressLine(LogLevel.Information, "Inside tran without commit");
            // rollback - commented: _ts.Complete();_
        }
        jobProgress.WriteProgressLine(LogLevel.Information, "After tran #2");

This is the console output - every log message inside the transaction are not showing up until commit and are disappearing when rolling back.

[pieceofsummer]

I guess it may be the issue inside Hangfire.SqlServer itself. Console just uses existing Storage API, but how transactions are made is up to storage implementation.

Particularly, Hangfire.SqlServer uses TransactionScopeOption.Required instead of TransactionScopeOption.RequiresNew when creating TransactionScope, so any commits Console makes inside your TransactionScope are automatically enlisted into it.

Probably @odinserj can comment on why it does so, and whether it is correct. If this is the expected behavior, I guess your easiest option would be making an extension method that wraps logging into another TransactionScope with TransactionScopeOption.Suppress flag, so that it goes to a separate transaction.

[hidegh]

In some cases, when you are finishing your job you want the work to be committed along with the state change, so using the usual Transactionscope.Required is IMO correct.

The issue although is that Hangfire.Console, since it's (or at least I use it as) a logging "library" to a given job, it should have a different behavior, and thus should create its own: TransactionScopeOption.RequiresNew whenever writing to SQL. What do you think, @pieceofsummer?

[hidegh]

Solution:

For those having the same issues, here's a solution, based on: https://github.com/AnderssonPeter/Hangfire.Console.Extensions/blob/9ef89d8743459e77c5a139d7241765d79ece8602/Hangfire.Console.Extensions/HangfireLogger.cs

With a little bit of abstraction:

using Microsoft.Extensions.Logging;

public interface IJobProgress
{
    public IJobProgressBar CreateProgressBar(string? name = null, double value = 0);
    public void WriteProgressLine(LogLevel level, string message, params object[] p);
}

public interface IJobProgressBar
{
    /// <summary>
    /// Expecting values in the range of 0..1!
    /// </summary>
    /// <param name="value"></param>
    void SetValue(double value);
}

And a very similar implementation - but with a new transaction scope with suppress placed around the logging:

using Hangfire.Console;
using Hangfire.Console.Extensions;
using Hangfire.Console.Progress;
using Hangfire.Server;
using Microsoft.Extensions.Logging;

namespace -- include your common interfaces --

public class HangfireSyncProgressBarWrapper : IJobProgressBar
{
    protected readonly IProgressBar progressBar;

    public HangfireSyncProgressBarWrapper(IProgressBar progressBar)
    {
        this.progressBar = progressBar;
    }

    public void SetValue(double value)
    {
        using (var ts = TransactionScopeBuilder.New(System.Transactions.TransactionScopeOption.Suppress))
        {
            progressBar.SetValue(100.0 * value);
            ts.Complete();
        }
    }

}

public class HangfireSyncProgress : IJobProgress
{
    public HangfireSyncProgress(PerformingContext performingContext, IProgressBarFactory progressBarFactory)
    {
        this.PerformingContext = performingContext;
        this.ProgressBarFactory = progressBarFactory;
    }

    protected PerformContext PerformingContext { get; }
    protected IProgressBarFactory ProgressBarFactory { get; }

    public IJobProgressBar CreateProgressBar(string? name = null, double value = 0)
    {
        IProgressBar progressBar;

        using (var ts = TransactionScopeBuilder.New(System.Transactions.TransactionScopeOption.Suppress))
        {
            progressBar = ProgressBarFactory.Create(name: name, value: value);
            ts.Complete();
        }
        
        var wrapper = new HangfireSyncProgressBarWrapper(progressBar);
        return wrapper;
    }

    public void WriteProgressLine(LogLevel level, string message, params object[] p)
    {
        using (var ts = TransactionScopeBuilder.New(System.Transactions.TransactionScopeOption.Suppress))
        {
            PerformingContext.WriteLine(GetConsoleColor(level), message, p);
            ts.Complete();
        }
    }

    /// <summary>
    /// https://github.com/AnderssonPeter/Hangfire.Console.Extensions/blob/9ef89d8743459e77c5a139d7241765d79ece8602/Hangfire.Console.Extensions/HangfireLogger.cs
    /// </summary>
    /// <param name="logLevel"></param>
    /// <returns></returns>
    protected ConsoleTextColor GetConsoleColor(LogLevel logLevel)
    {
        switch (logLevel)
        {
            case LogLevel.Critical:
                return ConsoleTextColor.Red;
            case LogLevel.Error:
                return ConsoleTextColor.Yellow;
            case LogLevel.Warning:
                return ConsoleTextColor.DarkYellow;
            case LogLevel.Information:
                return ConsoleTextColor.White;
            case LogLevel.Debug:
                return ConsoleTextColor.DarkGray;
            case LogLevel.Trace:
                return ConsoleTextColor.Gray;
            default:
                throw new ArgumentOutOfRangeException(nameof(logLevel));
        }
    }
}

The TransactionScopeBuilder.New is just a wrapper around the usual new TransactionScope(...)

[pieceofsummer]

Yeah, this is basically what I meant. But you should add a suppress stope to CreateProgressBar and SetValue too if you don't want progress bars to be messed up, since they also do database writes.

I hate the idea of introducing a conditional dependency to System.Transactions and a bunch of checks for Windows/non-Windows environments, especially in case it would be confirmed to be an issue on SqlServer storage's side. I can't think of a case when Hangfire storage operations may require to be enlisted into some outer transaction scope, and see RequiresNew as a valid choice there. But may also be missing something here.

[hidegh]

Thanx. Code in the comment above is updated.

For me (due to those wrappers) it's easier to do the patch around those 2 operations.
But, otherwise, I think this is something ConsoleStorage.cs should handle.

The reason for Hangfire to be enlisted in the operation is simple:

1. I use that feature when I just want to ensure that the work I've done in the job gets written to the DB with the succeeded Hangfire state.

2. When creating jobs, you need the creation and your logic to be tied - so you get same behavior as in the case of the outbox-pattern.