Finalizer Throws Unhandled Exception

[ShadowMarker789]

This caught me by surprise, found it in the Debug output log in Visual Studio

Exception thrown: 'libplctag.LibPlcTagException' in libplctag.dll System.Transactions Critical: 0 : <TraceRecord xmlns="http://schemas.microsoft.com/2004/10/E2ETraceEvent/TraceRecord" Severity="Critical"><TraceIdentifier>http://msdn.microsoft.com/TraceCodes/System/ActivityTracing/2004/07/Reliability/Exception/Unhandled</TraceIdentifier><Description>Unhandled exception</Description><AppDomain>[Redacted]</AppDomain><Exception><ExceptionType>libplctag.LibPlcTagException, libplctag, Version=1.0.13.0, Culture=neutral, PublicKeyToken=null</ExceptionType><Message>ErrorNotFound</Message><StackTrace> at libplctag.NativeTagWrapper.ThrowIfStatusNotOk(Nullable1 status) at libplctag.NativeTagWrapper.RemoveEvents() at libplctag.NativeTagWrapper.Dispose() at libplctag.Tag.Finalize()</StackTrace><ExceptionString>libplctag.LibPlcTagException: ErrorNotFound at libplctag.NativeTagWrapper.ThrowIfStatusNotOk(Nullable1 status) at libplctag.NativeTagWrapper.RemoveEvents() at libplctag.NativeTagWrapper.Dispose() at libplctag.Tag.Finalize()</ExceptionString></Exception></TraceRecord> An unhandled exception of type 'libplctag.LibPlcTagException' occurred in libplctag.dll ErrorNotFound

Unhandled Exception: libplctag.LibPlcTagException: ErrorNotFound at libplctag.NativeTagWrapper.ThrowIfStatusNotOk(Nullable`1 status) at libplctag.NativeTagWrapper.RemoveEvents() at libplctag.NativeTagWrapper.Dispose() at libplctag.Tag.Finalize()

For libplctag v 1.0.13

Do you want to do anything about this? I'm not sure what the implications are for throwing unhandled exceptions in the finalizer for a class.

[timyhac]

Thanks for raising this, I guess its coming from here.

Do you know what the error status is?

Ill do some research on canonical ways to handle this.

[ShadowMarker789]

I think the Tag wasn't found on the device, hence the "ErrorNotFound" in the libplctag exception.

Typically, we have a Dispose pattern in C#

The dispose pattern has a few portions

A public void Dispose(); method - this is the one implementing the IDisposable interface

a private void Dispose(bool disposing) method - this one helps us check whether we're being disposed by the programmer deliberately, or by the finalizer

The Finalizer should call Dispose(false); the IDisposable Dispose calls Dispose(true);

Consider the following example, which is the dispose pattern:

protected virtual void Dispose(bool disposing)
{
	if (!IsDisposed)
	{
		if (disposing)
		{
			// We will only enter this block if the programmer called Dispose
			// so it is safe to throw exceptions here
		}

		// DO NOT THROW HERE
		// TODO: free unmanaged resources (unmanaged objects) and override finalizer
		// TODO: set large fields to null
		IsDisposed = true;

	}
}
// TODO: override finalizer only if 'Dispose(bool disposing)' has code to free unmanaged resources
~Tag()
{
	// Do not change this code. Put cleanup code in 'Dispose(bool disposing)' method
	Dispose(disposing: false);
}
public void Dispose()
{
	// Do not change this code. Put cleanup code in 'Dispose(bool disposing)' method
	Dispose(disposing: true);
	GC.SuppressFinalize(this);
}

[timyhac]

I have spent a few weeks on and off trying to understand this. I was caught up on thinking that it was an issue with the disposer/finalizer in NativeTagWrapper but as you noted its simply that we aren't calling Dispose the right way from Tag and Tag<T> finalizers.

Thanks again!

[timyhac]

@ShadowMarker789 I am struggling to reproduce the issue. Are you able to reliably produce this problem and if so can you put together a test case?

Of course we could just implement the Dispose pattern, but without having a bug repro, how do we know we've fixed the right thing?

This is my attempt at a repro case, which doesn't throw in the finalizer.

Action dispose = () =>
{
    using var tag = new Tag()
    {
        Gateway = "127.0.0.1",
        Path = "1,0",
        PlcType = PlcType.ControlLogix,
        Protocol = Protocol.ab_eip,
        Name = "MyNonExistentTag",
        Timeout = TimeSpan.FromSeconds(1)
    };

    try
    {
       // Regardless of whether Initialize() is run or not our finalizer doesn't throw
        tag.Initialize();   // Fails because our tag doesn't exist. But we catch so we can continue onto our Disposer and Finalizer.
    }
    catch
    {
    }
    
    // Regardless of whether or not there is a call to Dispose(), the finalizer doesn't throw.            
    tag.Dispose();

};

dispose();
GC.Collect(0, GCCollectionMode.Forced);
GC.WaitForPendingFinalizers();              // Run finalizer, but shouldn't run any cleanup method because it is either already disposed, or was never initialized.

[ShadowMarker789]

I'll see if I can pen in some time later for a test, but I usually grab libplctag.Net from a Nuget package.

Is there a prerelease version I can grab that has the intended change for me to test?

[timyhac]

@ShadowMarker789 - I haven't made any changes to the code, so far I'm trying to reproduce the problem. Do you have some code that reliably reproduces the problem?

[ShadowMarker789]

I have hit it ... once again.

There seems to be some weird sequence you must enter and do to die like this. It brings down the entire application domain, it seems.

Just letting you know that I'm working on reproducing it.

libplctag.LibPlcTagException: ErrorNotFound
   at libplctag.NativeTagWrapper.ThrowIfStatusNotOk(Nullable`1 status)
   at libplctag.NativeTagWrapper.Dispose()
   at libplctag.NativeTagWrapper.Finalize()

[ShadowMarker789]

The repro process is very annoying.

It requires a way to deliberately strain the network to make tags timeout, such as clumsy

Use the following filter for CIP/EtherNet/IP traffic

You will want to alternate between having it drop all packets, and have it drop no packets. Have it 10 seconds fine, 10 seconds drop.

On the console window (since this is a console application) press the enter key every second or so, changing whether we're sending tags as eligible for collection or not.

Sometimes it takes a minute or two, but then I hit the exception above with the above call stack.

You need one tag that DOES exist, and one tag that does not.

Program.cs

using libplctag;

// INFO: libplctag.Net v 1.0.13 testing issue https://github.com/libplctag/libplctag.NET/issues/246
bool dieNow = false;
string gateway = "YOUR_GATEWAY_HERE";
string path = "1,0"; // rack 1, slot zero 
PlcType plcType = PlcType.ControlLogix;
Protocol protocol = Protocol.ab_eip;

TimeSpan timeout = TimeSpan.FromSeconds(5); // this seems excessively long. Turns out our network sucks badly 
// in production we use a timeout of 30 seconds instead  (；´д｀)ゞ  and we still get timeouts sometimes 
// some of these exist, some of these don't 
List<string> tagNames = new List<string>()
{
    // one of these tags exists, one of these doesn't 
    // which is confusing but whatever 
    "TAG_NOT_FOUND",
    "TAG_EXISTS",
};

List<Task> tasks = new List<Task>();

Console.WriteLine("Creating some tags... ");

int readSuccesses = 0;
int readFailures = 0;
int initFailures = 0;
int taskExits = 0;

Task.Run(async () =>
{
    while(true)
    {
        await Task.Delay(1000);
        Console.WriteLine($"Read Success={readSuccesses}, readFailures={readFailures}, initFailures={initFailures}, taskExits={taskExits}");
    }
});

Task.Run(async () =>
{
    while(true)
    {
        for (int i = 0; i < tagNames.Count; i++)
        {
            string tname = tagNames[i];
            // closure captures quite a few variables here, but whatever 
            _ = Task.Run(async () =>
            {
                Random r = new Random();
                await Task.Delay(r.Next(0, (int)timeout.TotalMilliseconds));
                try
                {
                    Tag t = new Tag()
                    {
                        Gateway = gateway,
                        Path = path,
                        PlcType = plcType,
                        Protocol = protocol,
                        Timeout = timeout,
                        Name = tname
                    };

                    await t.InitializeAsync();

                    while (!dieNow)
                    {
                        try
                        {
                            await t.ReadAsync();
                            Interlocked.Increment(ref readSuccesses);
                        }
                        catch (LibPlcTagException lptex)
                        {
                            // lol 
                            Interlocked.Increment(ref readFailures);
                        }
                    }
                }
                catch
                {
                    // Quash exception 
                    Interlocked.Increment(ref initFailures);
                }
                finally
                {
                    Interlocked.Increment(ref taskExits);
                }
            });
        }

        await Task.Delay(10);
    }
});

while (true)
{
    
    GC.Collect();
    Console.ReadLine();
    // pressing enter on the console swaps mode 
    dieNow = !dieNow;
    Console.WriteLine($"INFO: swapped mode, dieNow={dieNow}, also ran GC.Collect()");
    Console.WriteLine($"Read Success={readSuccesses}, readFailures={readFailures}, initFailures={initFailures}, taskExits={taskExits}");
}

Producing this call stack on death

[timyhac]

@ShadowMarker789 found the bug! Thanks so much for doing the work on this.

I was able to distill your repro code down to its simplest form as follows:

var tag = new Tag()
{
    Gateway = "127.0.0.1",
    Path = "1,0",
    PlcType = PlcType.ControlLogix,
    Protocol = Protocol.ab_eip,
    Name = "MyNonExistentTag",
    Timeout = TimeSpan.FromSeconds(5)
};

await tag.InitializeAsync();    // Still sets internal isInitialized despite failing!! It should throw but doesn't.

tag.Dispose();                  // Because it thinks it has been initialized, it tries to remove all callbacks, etc

The bug is that there should be an error thrown during InitializeAsync here like there is for ReadAsync and WriteAsync.

I think this would have been introduced when we made use of the CREATED event in underlying libplctag in https://github.com/libplctag/libplctag.NET/commit/b2016abc933d4e786cb1a87faed3b852086a188c

[jkoplo]

This is closed by #254 right?

[timyhac]

This is closed by #254 right?

Yes