NRE/Segfault in System.Net.Sockets tests on CI

[danmoseley]

https://mc.dot.net/#/user/danmosemsft/pr~2Fjenkins~2Fdotnet~2Fcorefx~2Fmaster~2F/test~2Ffunctional~2Fcli~2F/42e1badb4aca967a9bf44bb116a532ba73907fff/workItem/System.Net.Sockets.Tests/wilogs

2018-01-19 07:13:06,552: INFO: proc(54): run_and_log_output: Output: Starting:    System.Net.Sockets.Tests
2018-01-19 07:13:06,961: INFO: proc(54): run_and_log_output: Output: 
2018-01-19 07:13:06,964: INFO: proc(54): run_and_log_output: Output: Unhandled Exception: System.NullReferenceException: Object reference not set to an instance of an object.
2018-01-19 07:13:06,965: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.AcceptOperation.InvokeCallback() in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 543
2018-01-19 07:13:06,966: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.OperationQueue`1.ProcessQueue(SocketAsyncContext context) in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 947
2018-01-19 07:13:06,966: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) in /root/coreclr/src/mscorlib/shared/System/Threading/ExecutionContext.cs:line 151
2018-01-19 07:13:06,966: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ThreadPoolWorkQueue.Dispatch() in /root/coreclr/src/mscorlib/src/System/Threading/ThreadPool.cs:line 588
2018-01-19 07:13:10,427: INFO: proc(54): run_and_log_output: Output: /home/helixbot/dotnetbuild/work/5c4cfc68-2fd2-4829-b24a-3fd5bb05d287/Work/114dfc4a-d702-4db3-ae87-97330e05be36/Unzip/RunTests.sh: line 87: 85261 Aborted                 (core dumped) $RUNTIME_PATH/dotnet xunit.console.netcore.exe System.Net.Sockets.Tests.dll -xml testResults.xml -notrait Benchmark=true -notrait category=nonnetcoreapptests -notrait category=nonlinuxtests -notrait category=OuterLoop -notrait category=failing
2018-01-19 07:13:54,754: INFO: proc(54): run_and_log_output: Output: processing dump file /home/helixbot/dotnetbuild/work/5c4cfc68-2fd2-4829-b24a-3fd5bb05d287/Work/114dfc4a-d702-4db3-ae87-97330e05be36/Unzip/core.85261

https://dumpling.azurewebsites.net/api/dumplings/archived/a7435cfa4bbacb58ae78a2d15df620474bb8126f

History of failure

Day	Build	OS	Details
1/9	20180109.02	Fedora25	logs
1/13	20180113.01	Fedora26	logs
1/19	PR	RedHat73	logs and dump
1/22	20180122.02	Suse42.2	logs

[stephentoub]

@geoffkizer, this looks like https://github.com/dotnet/corefx/issues/25439, which was closed.

[karelz]

I have seen it in official daily runs as well (see internal OneNote for additional details from the logs). Top post updated with additional 3 hits since 12/17.

[geoffkizer]

We should add some asserts here to try to narrow down the problem.

[karelz]

Do you have some specific asserts in mind? We have a dump, naively I would expect that might give us a fair chance to root cause it.

[geoffkizer]

I missed the dump, sorry. Yes, we should look at that.

[stephentoub]

Failed again here:
https://mc.dot.net/#/user/dotnet-maestro-bot/pr~2Fjenkins~2Fdotnet~2Fcorefx~2Fmaster~2F/test~2Ffunctional~2Fcli~2F/4437384d75a512113231dff30101892db047ba31/workItem/System.Net.Sockets.Tests/wilogs

2018-02-22 16:45:39,869: INFO: proc(54): run_and_log_output: Output: Discovering: System.Net.Sockets.Tests
2018-02-22 16:45:40,479: INFO: proc(54): run_and_log_output: Output: Discovered:  System.Net.Sockets.Tests
2018-02-22 16:45:41,006: INFO: proc(54): run_and_log_output: Output: Starting:    System.Net.Sockets.Tests
2018-02-22 16:45:41,499: INFO: proc(54): run_and_log_output: Output: 
2018-02-22 16:45:41,501: INFO: proc(54): run_and_log_output: Output: Unhandled Exception: System.NullReferenceException: Object reference not set to an instance of an object.
2018-02-22 16:45:41,501: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.AcceptOperation.InvokeCallback() in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 543
2018-02-22 16:45:41,502: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.OperationQueue`1.ProcessQueue(SocketAsyncContext context) in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 947
2018-02-22 16:45:41,502: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in /root/coreclr/src/mscorlib/shared/System/Threading/ExecutionContext.cs:line 166
2018-02-22 16:45:41,503: INFO: proc(54): run_and_log_output: Output: --- End of stack trace from previous location where exception was thrown ---
2018-02-22 16:45:41,503: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ThreadPoolWorkQueue.Dispatch() in /root/coreclr/src/mscorlib/src/System/Threading/ThreadPool.cs:line 588
2018-02-22 16:45:42,187: INFO: proc(54): run_and_log_output: Output: /home/helixbot/dotnetbuild/work/99f937dc-2280-44d0-9ba3-2f059202da06/Work/307b4cfd-ae12-400e-b70a-595ecd0b8da9/Unzip/RunTests.sh: line 88:  6052 Aborted                 (core dumped) $RUNTIME_PATH/dotnet xunit.console.netcore.exe System.Net.Sockets.Tests.dll -xml testResults.xml -notrait Benchmark=true -notrait category=nonnetcoreapptests -notrait category=nonlinuxtests -notrait category=OuterLoop -notrait category=failing
2018-02-22 16:45:42,229: INFO: proc(54): run_and_log_output: Output: Dumpling has not been installed yet. Please run "DumplingHelper.py install_dumpling" before collect_dumps.
2018-02-22 16:45:42,232: INFO: proc(54): run_and_log_output: Output: ~/dotnetbuild/work/99f937dc-2280-44d0-9ba3-2f059202da06/Work/307b4cfd-ae12-400e-b70a-595ecd0b8da9/Unzip
2018-02-22 16:45:42,233: INFO: proc(54): run_and_log_output: Output: ----- end 16:45:42 ----- exit code 134 ----------------------------------------------------------
2018-02-22 16:45:42,235: INFO: proc(54): run_and_log_output: Output: Unable to find executable corerun
2018-02-22 16:45:42,237: INFO: proc(54): run_and_log_output: Output: Copying core file core to /tmp/coredumps
2018-02-22 16:45:42,458: INFO: proc(58): run_and_log_output: Exit Code: 134

[stephentoub]

Another one here:
https://mc.dot.net/#/user/Priya91/pr~2Fjenkins~2Fdotnet~2Fcorefx~2Fmaster~2F/test~2Ffunctional~2Fcli~2F/d3cfa938d7ebc52e652ca50ca08b38de920b42cb/workItem/System.Net.Sockets.Tests/wilogs

2018-02-27 15:08:54,872: INFO: proc(54): run_and_log_output: Output: Unhandled Exception: System.NullReferenceException: Object reference not set to an instance of an object.
2018-02-27 15:08:54,872: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.AcceptOperation.InvokeCallback() in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 543
2018-02-27 15:08:54,873: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.OperationQueue`1.ProcessQueue(SocketAsyncContext context) in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 947
2018-02-27 15:08:54,873: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in /root/coreclr/src/mscorlib/shared/System/Threading/ExecutionContext.cs:line 166
2018-02-27 15:08:54,873: INFO: proc(54): run_and_log_output: Output: --- End of stack trace from previous location where exception was thrown ---

[wfurt]

I'm setting up two Linux machines with tests running in loop. I'll post update if I'm able to reproduce it locally.

[geoffkizer]

Thanks. Let me know what you find.

It's interesting that we've only seen this with AcceptOperation. There must be something different we're doing for listen sockets that causes us to get into this state. Not sure what that would be, though...

[wfurt]

got repro on local Ubuntu 16.04 after 39 loops with full parallel Outerloop suite.
I'll try to see if it also happen in simplified scenario and I'll try to figure it out.

[ahsonkhan]

Failed again in dotnet/corefx#27729
Ubuntu.1604.Amd64.Open:Release-x64
https://mc.dot.net/#/user/AtsushiKan/pr~2Fjenkins~2Fdotnet~2Fcorefx~2Fmaster~2F/test~2Ffunctional~2Fcli~2F/42084fc0094813730ca5ab2a43d3297e508d0177/workItem/System.Net.Sockets.Tests/wilogs

[stephentoub]

Failed again here:
https://mc.dot.net/#/user/stephentoub/pr~2Fjenkins~2Fdotnet~2Fcorefx~2Fmaster~2F/test~2Ffunctional~2Fcli~2F/cf51308927f648c6f751dd4451c4a984744cb7b2/workItem/System.Net.Sockets.Tests/wilogs

2018-03-06 05:07:15,767: INFO: proc(54): run_and_log_output: Output: Unhandled Exception:    System.Net.Sockets.Tests.DualModeConnectToHostString.DualModeConnect_LoopbackDnsToHost_Helper [SKIP]
2018-03-06 05:07:15,768: INFO: proc(54): run_and_log_output: Output:       Condition(s) not met: \"LocalhostIsBothIPv4AndIPv6\"
2018-03-06 05:07:16,147: INFO: proc(54): run_and_log_output: Output: System.NullReferenceException: Object reference not set to an instance of an object.
2018-03-06 05:07:16,148: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.AcceptOperation.InvokeCallback() in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 543
2018-03-06 05:07:16,149: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.OperationQueue`1.ProcessQueue(SocketAsyncContext context) in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 947
2018-03-06 05:07:16,149: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in /root/coreclr/src/mscorlib/shared/System/Threading/ExecutionContext.cs:line 166
2018-03-06 05:07:16,150: INFO: proc(54): run_and_log_output: Output: --- End of stack trace from previous location where exception was thrown ---
2018-03-06 05:07:16,150: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ThreadPoolWorkQueue.Dispatch() in /root/coreclr/src/mscorlib/src/System/Threading/ThreadPool.cs:line 588

[stephentoub]

Failed again here:
https://mc.dot.net/#/user/maryamariyan/pr~2Fjenkins~2Fdotnet~2Fcorefx~2Fmaster~2F/test~2Ffunctional~2Fcli~2F/49f3e892a9ae4135542902f7099da4debe6069f1/workItem/System.Net.Sockets.Tests/wilogs

2018-03-06 01:47:32,301: INFO: proc(54): run_and_log_output: Output: Unhandled Exception: System.NullReferenceException: Object reference not set to an instance of an object.
2018-03-06 01:47:32,302: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.AcceptOperation.InvokeCallback() in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 543
2018-03-06 01:47:32,302: INFO: proc(54): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncContext.OperationQueue`1.ProcessQueue(SocketAsyncContext context) in /mnt/j/workspace/dotnet_corefx/master/linux-TGroup_netcoreapp+CGroup_Release+AGroup_x64+TestOuter_false_prtest/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncContext.Unix.cs:line 947
2018-03-06 01:47:32,302: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in /root/coreclr/src/mscorlib/shared/System/Threading/ExecutionContext.cs:line 166
2018-03-06 01:47:32,303: INFO: proc(54): run_and_log_output: Output: --- End of stack trace from previous location where exception was thrown ---
2018-03-06 01:47:32,303: INFO: proc(54): run_and_log_output: Output:    at System.Threading.ThreadPoolWorkQueue.Dispatch() in /root/coreclr/src/mscorlib/src/System/Threading/ThreadPool.cs:line 588

[stephentoub]

I've isolated a repro of this that always fails for me within a second, both debug and release:

using System;
using System.Net;
using System.Net.Sockets;
using System.Threading.Tasks;

class Program
{
    public static async Task Main()
    {
        for (int iter = 0; ; iter++)
        {
            using (var listener = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp))
            {
                listener.Bind(new IPEndPoint(IPAddress.Loopback, 0));
                listener.Listen(1);

                await Task.WhenAll(
                    Task.Run(async () => { try { await listener.AcceptAsync(); } catch {} }),
                    Task.Run(async () => { try { await listener.AcceptAsync(); } catch {} }),
                    Task.Run(() => listener.Dispose()));
                Console.WriteLine(iter);
            }
        }
    }
}