ArgumentNullException("logger") when disposing of ObservableSocket

[dchristoffersen-vivint]

I have a windows service that is constantly connecting to FreeSwitch and monitoring the servers. Unfortunately, when the FreeSwitch boxes fail over or are rebooted I keep hitting an ArgumentNullException in the GuardAgainstNullLogger method. I am getting logs out of log4net. It is only when it calls the dispose method that it fails and throws this error. Any ideas?

[dchristoffersen-vivint]

It appears that this is only a problem when we try to re-connect after a failed connection attempt. I fixed the problem by updating the Dispose method in the ObservableSocket.cs the following code:

[System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2213:DisposableFieldsShouldBeDisposed", MessageId = "received"
            ,Justification = "received is disposed of asynchronously, when the buffer has been flushed out by the consumers")]
        /// <summary>
        /// Releases unmanaged and - optionally - managed resources.
        /// </summary>
        /// <param name="disposing"><c>true</c> to release both managed and unmanaged resources; <c>false</c> to release only unmanaged resources.</param>
        protected virtual void Dispose(bool disposing)
        {
            if (!disposed)
            {
                disposed = true;

                if (Log == null)
                {
                    Log = LogProvider.GetLogger(GetType());
                }

                Log.Trace(() => "Disposing {0} (disposing:{1})".Fmt(GetType(), disposing));

                if (disposing)
                {
                    if (readSubscription != null)
                    {
                        readSubscription.Dispose();
                        readSubscription = null;
                    }

                    if (received != null)
                    {
                        received.CompleteAdding();
                    }
                }

                if (IsConnected)
                {
                    if (tcpClient != null)
                    {
                        tcpClient.Close();
                        tcpClient = null;
                        Log.Trace(() => "TcpClient closed");
                    }
                }

                Disposed?.Invoke(this, EventArgs.Empty);

                Log.Trace(() => "{0} Disposed".Fmt(GetType()));
            }
        }

[dchristoffersen-vivint]

I would love to get this fixed in the nuget package so I don't have to create a fork of the framework.

[danbarua]

I will take a look at this tomorrow, thanks for reporting!

[danbarua]

Try 0.6.7 on NuGet, I'll keep this issue open for now.

[dchristoffersen-vivint]

It looks like i am getting a null reference error from line 274 in the ObservableSocket.cs file. The method appears to be null.

[danbarua]

OK, I know what the problem is - 0.6.8 has a fix for this specific issue in ObservableSocket, I will fix non thread-safe .Dispose() calls elsewhere and push a new version for that shortly.

[danbarua]

0.6.9 should have fixed this globally now - the issue was multiple threads calling Dispose() at the same time.

[dchristoffersen-vivint]

It looks like the Disposed method call is still throwing a null reference error. Line 267 in ObservableSocket.cs needs to be checked to see if it is Null prior to executing the delegate function call.

[danbarua]

Argh, I would have thought we'd be covered by ensuring Dispose() was only called once. I guess the empty event handler has been garbage collected at this point - I've not seen this behaviour at my end. I've just pushed 0.6.10 to NuGet.

[dchristoffersen-vivint]

I am really sorry, now I am getting a null reference on EventSocket.cs line 520.

[dchristoffersen-vivint]

The best way to replicate this issue is to cycle freeswitch on and off. I typically turn it off for a few minutes and allow a couple of retry events to occur and then turn it back on. I test it by having the freeswitch server turned on when I start the app and the next time I start the app I have freeswitch off. It typically throws the null reference error on the second or third attempt to connect. Sometimes it will cycle without issues until it successfully connects. I forked the base for the time being and I am simply checking for null values on the Log and the Disposed objects. That seems to have resolved the issue.

[danbarua]

No worries re: reporting issues, this is a relatively new lib and we're all flushing out the gremlins in different use cases and it benefits everyone.

Re: retry events? I haven't coded in any reconnection logic - is this specific to your app/fork? Are you trying to re-use an EventSocketinstance?

[danbarua]

re: Null Reference Exception on line 520:

if (!disposed.EnsureCalledOnce())

The only thing I can think of is that the Garbage Collector has cleaned up the readonly field which we are accessing in the Dispose method...

[danbarua]

Possibly fixed in c5c742a1aa6e0c2ca132b8a361785d8c35afcdc7 Wait for feedback.

[dchristoffersen-vivint]

So, it took a couple of retries in order to get it to fail. My code will wait and then retry a connection attempt until it is successful. However, on the third or fourth retry attempt I got a null value reference on the interlockedBoolean.CompareExchange(true, false). Line 82 in InterlockedBoolean.cs. Which is called by Line 571 in the EventSocket.cs. Which was called by line 149 in ObservableSocket.cs. I added a null reference check and it seems to have corrected the problem. The code is below; lines 78 - 84.

internal static class InterlockedBooleanExtensions { internal static bool EnsureCalledOnce(this InterlockedBoolean interlockedBoolean) { return interlockedBoolean?.CompareExchange(true, false) ?? false; } }

[danbarua]

Yep, grab the latest off master and that is fixed.

On Friday, 4 March 2016, dchristoffersen-vivint notifications@github.com wrote:

So, it took a couple of retries in order to get it to fail. My code will wait and then retry a connection attempt until it is successful. However, on the third or fourth retry attempt I got a null value reference on the interlockedBoolean.CompareExchange(true, false). Line 82 in InterlockedBoolean.cs. Which is called by Line 571 in the EventSocket.cs. Which was called by line 149 in ObservableSocket.cs. I added a null reference check and it seems to have corrected the problem. The code is below; lines 78 - 84.

internal static class InterlockedBooleanExtensions { internal static bool EnsureCalledOnce(this InterlockedBoolean interlockedBoolean) { return interlockedBoolean?.CompareExchange(true, false) ?? false; } }

— Reply to this email directly or view it on GitHub https://github.com/danbarua/NEventSocket/issues/26#issuecomment-192398708 .

[danbarua]

https://github.com/danbarua/NEventSocket/commit/5a9c2d7327687271cbd3ca21a239f7373b7133d2

Woops I missed out ObservableSocket in that commit, added the check now.

Dan Barua

On Friday, 4 March 2016 at 20:59, Dan Barua wrote:

Yep, grab the latest off master and that is fixed.

On Friday, 4 March 2016, dchristoffersen-vivint <notifications@github.com (mailto:notifications@github.com)> wrote:

So, it took a couple of retries in order to get it to fail. My code will wait and then retry a connection attempt until it is successful. However, on the third or fourth retry attempt I got a null value reference on the interlockedBoolean.CompareExchange(true, false). Line 82 in InterlockedBoolean.cs. Which is called by Line 571 in the EventSocket.cs. Which was called by line 149 in ObservableSocket.cs. I added a null reference check and it seems to have corrected the problem. The code is below; lines 78 - 84.
internal static class InterlockedBooleanExtensions { internal static bool EnsureCalledOnce(this InterlockedBoolean interlockedBoolean) { return interlockedBoolean?.CompareExchange(true, false) ?? false; } }

— Reply to this email directly or view it on GitHub (https://github.com/danbarua/NEventSocket/issues/26#issuecomment-192398708).

[danbarua]

I have a load test that spams FreeSwitch with N inbound socket connections, they subscribe to heartbeat events then disconnect and report ok once they have received the first heartbeat. Running without the debugger/profiler attached I can get 1000 clients connecting at once without any problems. I am seeing weird issues with messages being truncated only when debugging in VS2015 with the performance profilers attached. Fingers crossed this is related only to profiling overhead and does not manifest in production.

[dchristoffersen-vivint]

It is crashing out on line 305 inside of LibLog.cs. The argumentNullException is not being caught by the try-catch blocks wrapped around the using or inside of the eventhandlers. It just crashes the application.

private static void GuardAgainstNullLogger(ILog logger) { if (logger == null) { throw new ArgumentNullException("logger"); } }

[dchristoffersen-vivint]

It is happening because of a call on line 242 in ObservableSocket.cs.

[danbarua]

So I've learnt from this that readonly fields can be set to null when Dispose() is called from a finalizer...

[danbarua]

@dchristoffersen-vivint any better? Dealing with disposals/cleanups in an async multithreaded world is a PITA.

[dchristoffersen-vivint]

Yeah, you aren't kidding :). The latest master build has resolved this nullreference error. We just pushed the build to staging. I will let you know how testing and the push goes today.

[danbarua]

Related to #28