I have a Background Service that performs some tasks and jobs on a long running thread. For simplicity, We'll consider this as a scheduler that makes an async SQL call and repeats. Now I use AsyncLocal to store metadata for logging purpose on the service and I want to group each repetition of the task as a transaction. I figured that unlike web applications the BackgroundService will have a single AsyncLocal(ExecutionContext) object that I have to clear after every repetition (every SQL call in this example). Coming to the problem, I cannot seem to clean up the object .
Here is the implementation of my AsyncLocal storage class.
public class AsyncLocalStorage<T> : ILocalStorage<T>
{
private readonly AsyncLocal<T> _context;
public AsyncLocalStorage()
{
_context = new AsyncLocal<T>(OnValueChanged);
}
private static void OnValueChanged(AsyncLocalValueChangedArgs<T> args)
{
Log("OnValueChanged! Prev: {0} ; Current: {1}", RuntimeHelpers.GetHashCode(args.PreviousValue), RuntimeHelpers.GetHashCode(args.CurrentValue));
}
public T GetData()
{
try
{
return _context.Value;
}
catch (Exception ex)
{
Log("Ex: " + ex.ToString());
}
return default(T);
}
public void SetData(T value)
{
_context.Value = value;
}
public void Clear()
{
_context.Value = default(T);
}
}
Here , I set my metadata to the AsyncLocal object and then I call the Clear function . But the object instance remains . I have attached logs for further reference.
02-05-2024 20:10:38 - [4:(DEBUG)<t:4>] - [TName: ]TRANSACTION STARTED (The AsyncLocal Object is created and I assign my object "Transaction" using context.SetData())
02-05-2024 20:10:38 - [1:(ERROR)<t:4>] - OnValueChanged! Prev: 0 ; Current: 5773521
02-05-2024 20:10:39 - [4:(DEBUG)<t:4>] - [TName: ]The async SQL call is made.... (The Transaction object is modified context.GetData() . I guess the obj is passed to thread 9 )
02-05-2024 20:10:39 - [1:(ERROR)<t:9>] - OnValueChanged! Prev: 0 ; Current: 5773521
02-05-2024 20:10:39 - [4:(DEBUG)<t:4>] - [TName: ]---- random things are taken care off using the Transaction object that resulted in the following OnValueChanged logs .
02-05-2024 20:10:39 - [1:(ERROR)<t:5>] - OnValueChanged! Prev: 0 ; Current: 5773521
02-05-2024 20:10:39 - [1:(ERROR)<t:9>] - OnValueChanged! Prev: 5773521 ; Current: 0
02-05-2024 20:10:39 - [1:(ERROR)<t:5>] - OnValueChanged! Prev: 5773521 ; Current: 0
02-05-2024 20:10:39 - [1:(ERROR)<t:5>] - OnValueChanged! Prev: 0 ; Current: 5773521
02-05-2024 20:10:39 - [1:(ERROR)<t:5>] - OnValueChanged! Prev: 5773521 ; Current: 0
02-05-2024 20:10:39 - [4:(DEBUG)<t:4>] - [TName: ]The Async SQL call returned a Task object .
02-05-2024 20:10:39 - [1:(ERROR)<t:9>] - OnValueChanged! Prev: 0 ; Current: 5773521
02-05-2024 20:10:39 - [4:(DEBUG)<t:4>] - [TName: ]Processing of the metadata done on thread 4 is over.
02-05-2024 20:10:39 - [1:(ERROR)<t:4>] - OnValueChanged! Prev: 5773521 ; Current: 0
02-05-2024 20:10:39 - [4:(DEBUG)<t:9>] - [TName: ]Most of the processing on Thread 9 is also over and The Task returned by SQL call has finished.
02-05-2024 20:10:39 - [4:(DEBUG)<t:9>] - [TName: ]Now the Transaction object is fetched with context.GetData() and is Loaded into a Thread Processor that runs independently using "ThreadPool.QueueWorkItem(Event, transaction) , which happens to be thread 10"
02-05-2024 20:10:39 - [1:(ERROR)<t:10>] - OnValueChanged! Prev: 0 ; Current: 5773521
02-05-2024 20:10:39 - [4:(DEBUG)<t:9>] - [TName: ]Everything seems to be over and its time to call context.Clear() //called.
02-05-2024 20:10:39 - [1:(ERROR)<t:9>] - OnValueChanged! Prev: 5773521 ; Current: 0
02-05-2024 20:10:39 - [4:(DEBUG)<t:9>] - [TName: ]Tried getting the transaction object here to verify using context.GetData(), returned null here.
02-05-2024 20:10:39 - [4:(DEBUG)<t:10>] - [TName: ProcessThread]Working with the transaction object reference in the Event thread.
02-05-2024 20:10:39 - [4:(DEBUG)<t:10>] - [TName: ProcessThread]Also working with the transaction object that is passed to this thread processor. Have no idea why the below log has occured.
02-05-2024 20:10:39 - [1:(ERROR)<t:10>] - OnValueChanged! Prev: 5773521 ; Current: 0 (I am sure the transaction object goes out of scope here)
02-05-2024 20:10:39 - [4:(DEBUG)<t:4>] - [TName: ]TRANSACTION STARTED (new repetition, calling the GetData function again before creating a new transaction object and assigning. I only assign a new object if it is null)
02-05-2024 20:10:40 - [1:(ERROR)<t:4>] - OnValueChanged! Prev: 0 ; Current: 5773521
02-05-2024 20:10:40 - [4:(DEBUG)<t:4>] - [TName: ] Suprise suprise!! it is not NULL. I have no idea why it isn't .
02-05-2024 20:10:40 - [4:(DEBUG)<t:4>] - [TName: ]I have already cleared all the component objects in the transaction object . A New transaction object is needed here.
Why does this happen, Is there something I am missing ?
EDIT : The minimal reproduceable example is below. I have tried to make it small
public class Worker : BackgroundService
{
private readonly ILogger<Worker> _logger;
private readonly BackgroundTask _backgroundtask;
public Worker(ILogger<Worker> logger, BackgroundTask task)
{
_logger = logger;
_backgroundtask = task;
}
protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
while (!stoppingToken.IsCancellationRequested)
{
_logger.LogInformation("Worker running at: {time}", DateTimeOffset.Now);
_backgroundtask.MakeTask();
await Task.Delay(1000, stoppingToken);
}
}
}
public sealed class BackgroundTask
{
private readonly ILogger<BackgroundTask> _logger;
public BackgroundTask(ILogger<BackgroundTask> logger)
{
_logger = logger;
}
public void MakeTask()
{
Transactions trans = TransactionService.GetCurrentTransaction();
if(trans == null)
{
Console.WriteLine("[T:<{0}>] There is no TransactionObject", Thread.CurrentThread.ManagedThreadId);
trans = TransactionService.GetOrCreateTransaction();
}
else
{
Console.WriteLine("[T:<{0}>] There is a Transaction Object", Thread.CurrentThread.ManagedThreadId);
}
trans.PrintTransactionName();
Task.Run(() =>
{
trans.SetTransactionName("transaction2");
trans.PrintTransactionName();
trans.ClearEverything();
});
}
}
public class TransactionService
{
private static AsyncLocalStorage<Transactions> transactionContext;
static TransactionService()
{
transactionContext = new AsyncLocalStorage<Transactions>();
}
public static Transactions GetCurrentTransaction()
{
return transactionContext.GetData();
}
public static Transactions GetOrCreateTransaction()
{
var transaction = GetCurrentTransaction();
if (transaction == null)
{
transaction = new Transactions("Transaction1");
transactionContext.SetData(transaction);
}
return transaction;
}
public static void RemoveOutstandingTransactions()
{
transactionContext.Clear();
}
}
public class Transactions
{
private string transactionName;
public Transactions(string trans)
{
transactionName = trans;
}
public void SetTransactionName(string trans)
{
transactionName = trans;
}
public void PrintTransactionName()
{
if (!string.IsNullOrEmpty(transactionName))
{
Console.WriteLine("[T:<{0}>] The transactionName is {1}", Thread.CurrentThread.ManagedThreadId, transactionName);
}
}
public void ClearEverything()
{
transactionName = null;
Console.WriteLine("[T:<{0}>] The Transaction Object is being cleared", Thread.CurrentThread.ManagedThreadId);
TransactionService.RemoveOutstandingTransactions();
// Just checking if the object is cleared in this thread.
if(TransactionService.GetCurrentTransaction() == null)
{
Console.WriteLine("[T:<{0}>] The Transaction Object is null after clearing", Thread.CurrentThread.ManagedThreadId);
}
}
}
Make a Worker-Service with .NET core like the above example. Why is there a Transaction Object at the start of the next repetition after clearing the AsyncLocal object. The Logs will go something like ...
[T:<1>] There is no TransactionObject
[T:<1>] OnValueChanged! Prev: 0 ; Current: 72766
[T:<1>] The transactionName is Transaction1
[T:<9>] OnValueChanged! Prev: 0 ; Current: 72766
[T:<9>] The transactionName is transaction2
[T:<1>] OnValueChanged! Prev: 72766 ; Current: 0
[T:<9>] The Transaction Object is being cleared
[T:<9>] OnValueChanged! Prev: 72766 ; Current: 0
[T:<9>] The Transaction Object is null after clearing
[T:<6>] There is a Transaction Object
[T:<6>] OnValueChanged! Prev: 72766 ; Current: 0
[T:<9>] OnValueChanged! Prev: 0 ; Current: 72766
[T:<9>] The transactionName is transaction2
[T:<9>] The Transaction Object is being cleared
[T:<9>] OnValueChanged! Prev: 72766 ; Current: 0
[T:<9>] The Transaction Object is null after clearing
[T:<9>] OnValueChanged! Prev: 0 ; Current: 72766
Also why is the object hash the same ?
Why does this happen? Is there something I am missing?
Yes, AsyncLocal works as a kind of copy-on-write stack of "async flow". In your case (if simplify and concentrate only on interesting "async flows"), MakeTask is putting the first value into AsyncLocal, so basically to an asyncflow#1. When you run Task.Run(), it creates a new asyncflow#2. Clearing in your case is happening in asyncflow#2, which has no effect on asyncflow#1 because of copy-on-write behavior, but your worker is still in asyncflow#1 where your object was the firstly created transaction. Because of that, you always see the same hash. To achieve the behavior you wish, you can just make the method MakeTask async even without awaits inside but await it in your while loop; it will force the creation of a new "async flow", and the output will be like this:
[T:<7>] There is no TransactionObject
OnValueChanged! Prev: 0 ; Current: 11429296
[T:<7>] The transactionName is Transaction1
[T:<7>] The transactionName is transaction2
[T:<7>] The Transaction Object is being cleared
OnValueChanged! Prev: 11429296 ; Current: 0
[T:<7>] The Transaction Object is null after clearing
[T:<7>] There is no TransactionObject
OnValueChanged! Prev: 0 ; Current: 41622463
[T:<7>] The transactionName is Transaction1
[T:<7>] The transactionName is transaction2
[T:<7>] The Transaction Object is being cleared
OnValueChanged! Prev: 41622463 ; Current: 0
[T:<7>] The Transaction Object is null after clearing
info: WorkerService1.Worker[0]
Worker running at: 05/15/2024 22:59:18 +03:00
[T:<7>] There is no TransactionObject
info: WorkerService1.Worker[0]
Worker running at: 05/15/2024 22:59:19 +03:00
OnValueChanged! Prev: 0 ; Current: 31364015
[T:<7>] The transactionName is Transaction1
[T:<7>] The transactionName is transaction2
[T:<7>] The Transaction Object is being cleared
OnValueChanged! Prev: 31364015 ; Current: 0
[T:<7>] The Transaction Object is null after clearing