Failing unit tests in clean macOS development environment

[yaakov-h]

I've followed the instructions outlined here, and after running ./build-tests.sh, two unit tests failed:

      <test name="System.Diagnostics.Tests.ProcessTests.TestProcessStartTime" type="System.Diagnostics.Tests.ProcessTests" method="TestProcessStartTime" time="0.457767" result="Fail">
        <failure exception-type="Xunit.Sdk.InRangeException">
          <message><![CDATA[Assert.InRange() Failure\r\nRange:  (1/15/17 8:51:09 AM - 1/15/17 8:51:15 AM)\r\nActual: 1/15/17 12:36:59 AM]]></message>
          <stack-trace><![CDATA[   at System.Diagnostics.Tests.ProcessTests.TestProcessStartTime() in /Users/yaakov/Development/ThirdParty/corefx/src/System.Diagnostics.Process/tests/ProcessTests.cs:line 416]]></stack-trace>
        </failure>
      </test>

       <test name="System.Globalization.Tests.DateTimeFormatInfoGetDayName.GetDayName(format: DateTimeFormatInfo { AbbreviatedDayNames = [\&quot;dim.\&quot;, \&quot;lun.\&quot;, \&quot;mar.\&quot;, \&quot;mer.\&quot;, \&quot;jeu.\&quot;, ...], AbbreviatedMonthGenitiveNames = [\&quot;janv.\&quot;, \&quot;févr.\&quot;, \&quot;mars\&quot;, \&quot;avr.\&quot;, \&quot;mai\&quot;, ...], AbbreviatedMonthNames = [\&quot;janv.\&quot;, \&quot;févr.\&quot;, \&quot;mars\&quot;, \&quot;avr.\&quot;, \&quot;mai\&quot;, ...], AMDesignator = \&quot;AM\&quot;, Calendar = GregorianCalendar { AlgorithmType = SolarCalendar, CalendarType = Localized, Eras = [...], IsReadOnly = False, MaxSupportedDateTime = 9999-12-31T23:59:59.9999999, ... }, ... }, expected: [\&quot;Dimanche\&quot;, \&quot;Lundi\&quot;, \&quot;Mardi\&quot;, \&quot;Mercredi\&quot;, \&quot;Jeudi\&quot;, ...])" type="System.Globalization.Tests.DateTimeFormatInfoGetDayName" method="GetDayName" time="0.000331" result="Fail">
        <failure exception-type="Xunit.Sdk.EqualException">
          <message><![CDATA[Assert.Equal() Failure\n          ↓ (pos 0)\nExpected: Dimanche\nActual:   dimanche\n          ↑ (pos 0)]]></message>
          <stack-trace><![CDATA[   at System.Globalization.Tests.DateTimeFormatInfoGetDayName.GetDayName(DateTimeFormatInfo format, String[] expected) in /Users/yaakov/Development/ThirdParty/corefx/src/System.Globalization/tests/DateTimeFormatInfo/DateTimeFormatInfoGetDayName.cs:line 44]]></stack-trace>
        </failure>
      </test>

This occurred on macOS 10.12.2 (16C67).

[karelz]

Did they fail just once?
We might need to slit them into separate issues.

[yaakov-h]

The second time I set up a clean workspace those two failed, plus another one in WebProxy. I didn't catch the name at the time.

[danmoseley]

The second one looks like it needs the same workaround as in dotnet/corefx#6257. I don't see an active issue to make the tests work on those platforms. cc @tarekgh for info that this is happening on Mac.

[danmoseley]

The first one is odd, it means Process.GetCurrentProcess().StartTime.ToUniversalTime() was several hours (but not an even difference, like a timezone) different to DateTime.UtcNow.

[yaakov-h]

Just set up a clean workspace again and built and re-tested.

Build warnings:

/private/tmp/corefx/Tools/Microsoft.Common.CurrentVersion.targets(1819,5): warning MSB3277: Found conflicts between different versions of the same dependent assembly that could not be resolved.  These reference conflicts are listed in the build log when log verbosity is set to detailed. [/private/tmp/corefx/src/Tools/CoreFx.Tools/CoreFx.Tools.csproj]
/private/tmp/corefx/src/System.Configuration.ConfigurationManager/src/Resources/Strings.resx : warning MSB3568: Duplicate resource name "Config_base_unrecognized_element" is not allowed, ignored. [/private/tmp/corefx/src/System.Configuration.ConfigurationManager/src/System.Configuration.ConfigurationManager.csproj]

Then, failed tests:

/private/tmp/corefx/Tools/tests.targets(210,5): warning :    System.Diagnostics.Process.Tests  Total: 108, Errors: 0, Failed: 1, Skipped: 0, Time: 23.338s [/private/tmp/corefx/src/System.Diagnostics.Process/tests/System.Diagnostics.Process.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(210,5): warning MSB3073: The command "/private/tmp/corefx/bin/AnyOS.AnyCPU.Debug/System.Diagnostics.Process.Tests/netstandard/RunTests.sh /private/tmp/corefx/Tools/testdotnetcli" exited with code 1. [/private/tmp/corefx/src/System.Diagnostics.Process/tests/System.Diagnostics.Process.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(210,5): warning :    System.Globalization.Tests  Total: 1635, Errors: 0, Failed: 2, Skipped: 0, Time: 4.899s [/private/tmp/corefx/src/System.Globalization/tests/System.Globalization.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(210,5): warning MSB3073: The command "/private/tmp/corefx/bin/AnyOS.AnyCPU.Debug/System.Globalization.Tests/netstandard/RunTests.sh /private/tmp/corefx/Tools/testdotnetcli" exited with code 1. [/private/tmp/corefx/src/System.Globalization/tests/System.Globalization.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(210,5): warning :    System.Net.WebProxy.Tests  Total: 21, Errors: 0, Failed: 1, Skipped: 0, Time: 6.973s [/private/tmp/corefx/src/System.Net.WebProxy/tests/System.Net.WebProxy.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(210,5): warning MSB3073: The command "/private/tmp/corefx/bin/AnyOS.AnyCPU.Debug/System.Net.WebProxy.Tests/netstandard/RunTests.sh /private/tmp/corefx/Tools/testdotnetcli" exited with code 1. [/private/tmp/corefx/src/System.Net.WebProxy/tests/System.Net.WebProxy.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(210,5): warning :    System.Net.NameResolution.Pal.Tests  Total: 13, Errors: 0, Failed: 2, Skipped: 0, Time: 10.575s [/private/tmp/corefx/src/System.Net.NameResolution/tests/PalTests/System.Net.NameResolution.Pal.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(210,5): warning MSB3073: The command "/private/tmp/corefx/bin/Unix.AnyCPU.Debug/System.Net.NameResolution.Pal.Tests/netstandard/RunTests.sh /private/tmp/corefx/Tools/testdotnetcli" exited with code 1. [/private/tmp/corefx/src/System.Net.NameResolution/tests/PalTests/System.Net.NameResolution.Pal.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(218,5): error : One or more tests failed while running tests from 'System.Diagnostics.Process.Tests' please check /private/tmp/corefx/bin/AnyOS.AnyCPU.Debug/System.Diagnostics.Process.Tests/netstandard/testResults.xml for details! [/private/tmp/corefx/src/System.Diagnostics.Process/tests/System.Diagnostics.Process.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(218,5): error : One or more tests failed while running tests from 'System.Globalization.Tests' please check /private/tmp/corefx/bin/AnyOS.AnyCPU.Debug/System.Globalization.Tests/netstandard/testResults.xml for details! [/private/tmp/corefx/src/System.Globalization/tests/System.Globalization.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(218,5): error : One or more tests failed while running tests from 'System.Net.WebProxy.Tests' please check /private/tmp/corefx/bin/AnyOS.AnyCPU.Debug/System.Net.WebProxy.Tests/netstandard/testResults.xml for details! [/private/tmp/corefx/src/System.Net.WebProxy/tests/System.Net.WebProxy.Tests.csproj]
/private/tmp/corefx/Tools/tests.targets(218,5): error : One or more tests failed while running tests from 'System.Net.NameResolution.Pal.Tests' please check /private/tmp/corefx/bin/Unix.AnyCPU.Debug/System.Net.NameResolution.Pal.Tests/netstandard/testResults.xml for details! [/private/tmp/corefx/src/System.Net.NameResolution/tests/PalTests/System.Net.NameResolution.Pal.Tests.csproj]
Command execution failed with exit code 1.

Some failures are the same as above, some look new.

      <test name="System.Diagnostics.Tests.ProcessTests.TestProcessStartTime" type="System.Diagnostics.Tests.ProcessTests" method="TestProcessStartTime" time="0.292751" result="Fail">
        <failure exception-type="Xunit.Sdk.InRangeException">
          <message><![CDATA[Assert.InRange() Failure\r\nRange:  (1/22/17 5:50:13 AM - 1/22/17 5:50:19 AM)\r\nActual: 1/22/17 4:24:11 AM]]></message>
          <stack-trace><![CDATA[   at System.Diagnostics.Tests.ProcessTests.TestProcessStartTime() in /private/tmp/corefx/src/System.Diagnostics.Process/tests/ProcessTests.cs:line 416]]></stack-trace>
        </failure>
      </test>

Interesting that the difference between process start time and current time here is different to the previous failure in the original post above.

       <test name="System.Globalization.Tests.DateTimeFormatInfoGetAbbreviatedDayName.GetAbbreviatedDayName(info: DateTimeFormatInfo { AbbreviatedDayNames = [\&quot;dim.\&quot;, \&quot;lun.\&quot;, \&quot;mar.\&quot;, \&quot;mer.\&quot;, \&quot;jeu.\&quot;, ...], AbbreviatedMonthGenitiveNames = [\&quot;janv.\&quot;, \&quot;févr.\&quot;, \&quot;mars\&quot;, \&quot;avr.\&quot;, \&quot;mai\&quot;, ...], AbbreviatedMonthNames = [\&quot;janv.\&quot;, \&quot;févr.\&quot;, \&quot;mars\&quot;, \&quot;avr.\&quot;, \&quot;mai\&quot;, ...], AMDesignator = \&quot;AM\&quot;, Calendar = GregorianCalendar { AlgorithmType = SolarCalendar, CalendarType = Localized, Eras = [...], IsReadOnly = False, MaxSupportedDateTime = 9999-12-31T23:59:59.9999999, ... }, ... }, expected: [\&quot;Dim.\&quot;, \&quot;Lun.\&quot;, \&quot;Mar.\&quot;, \&quot;Mer.\&quot;, \&quot;Jeu.\&quot;, ...])" type="System.Globalization.Tests.DateTimeFormatInfoGetAbbreviatedDayName" method="GetAbbreviatedDayName" time="0.000306" result="Fail">
        <failure exception-type="Xunit.Sdk.EqualException">
          <message><![CDATA[Assert.Equal() Failure\n          ↓ (pos 0)\nExpected: Dim.\nActual:   dim.\n          ↑ (pos 0)]]></message>
          <stack-trace><![CDATA[   at System.Globalization.Tests.DateTimeFormatInfoGetAbbreviatedDayName.GetAbbreviatedDayName(DateTimeFormatInfo info, String[] expected) in /private/tmp/corefx/src/System.Globalization/tests/DateTimeFormatInfo/DateTimeFormatInfoGetAbbreviatedDayName.cs:line 43]]></stack-trace>
        </failure>
      </test>

      <test name="System.Globalization.Tests.DateTimeFormatInfoGetDayName.GetDayName(format: DateTimeFormatInfo { AbbreviatedDayNames = [\&quot;dim.\&quot;, \&quot;lun.\&quot;, \&quot;mar.\&quot;, \&quot;mer.\&quot;, \&quot;jeu.\&quot;, ...], AbbreviatedMonthGenitiveNames = [\&quot;janv.\&quot;, \&quot;févr.\&quot;, \&quot;mars\&quot;, \&quot;avr.\&quot;, \&quot;mai\&quot;, ...], AbbreviatedMonthNames = [\&quot;janv.\&quot;, \&quot;févr.\&quot;, \&quot;mars\&quot;, \&quot;avr.\&quot;, \&quot;mai\&quot;, ...], AMDesignator = \&quot;AM\&quot;, Calendar = GregorianCalendar { AlgorithmType = SolarCalendar, CalendarType = Localized, Eras = [...], IsReadOnly = False, MaxSupportedDateTime = 9999-12-31T23:59:59.9999999, ... }, ... }, expected: [\&quot;Dimanche\&quot;, \&quot;Lundi\&quot;, \&quot;Mardi\&quot;, \&quot;Mercredi\&quot;, \&quot;Jeudi\&quot;, ...])" type="System.Globalization.Tests.DateTimeFormatInfoGetDayName" method="GetDayName" time="0.017261" result="Fail">
        <failure exception-type="Xunit.Sdk.EqualException">
          <message><![CDATA[Assert.Equal() Failure\n          ↓ (pos 0)\nExpected: Dimanche\nActual:   dimanche\n          ↑ (pos 0)]]></message>
          <stack-trace><![CDATA[   at System.Globalization.Tests.DateTimeFormatInfoGetDayName.GetDayName(DateTimeFormatInfo format, String[] expected) in /private/tmp/corefx/src/System.Globalization/tests/DateTimeFormatInfo/DateTimeFormatInfoGetDayName.cs:line 44]]></stack-trace>
        </failure>
      </test>

These two Globalisation ones look like capitalisation issues.

      <test name="System.Net.Tests.WebProxyTest.BypassOnLocal_MatchesExpected" type="System.Net.Tests.WebProxyTest" method="BypassOnLocal_MatchesExpected" time="0" result="Fail">
        <failure exception-type="System.Net.Internals.SocketExceptionFactory+ExtendedSocketException">
          <message><![CDATA[System.Net.Internals.SocketExceptionFactory+ExtendedSocketException : Device not configured]]></message>
          <stack-trace><![CDATA[   at System.Net.Dns.HostResolutionEndHelper(IAsyncResult asyncResult) in /private/tmp/corefx/src/System.Net.NameResolution/src/System/Net/DNS.cs:line 422
   at System.Net.Dns.EndGetHostEntry(IAsyncResult asyncResult) in /private/tmp/corefx/src/System.Net.NameResolution/src/System/Net/DNS.cs:line 561
   at System.Net.Dns.<>c.<GetHostEntryAsync>b__27_1(IAsyncResult asyncResult) in /private/tmp/corefx/src/System.Net.NameResolution/src/System/Net/DNS.cs:line 651
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at System.Net.Tests.WebProxyTest.<BypassOnLocal_MemberData>d__10.MoveNext() in /private/tmp/corefx/src/System.Net.WebProxy/tests/WebProxyTest.cs:line 146
   at System.Linq.Enumerable.SelectEnumerableIterator`2.MoveNext() in /private/tmp/corefx/src/System.Linq/src/System/Linq/Select.cs:line 133]]></stack-trace>
        </failure>
      </test>

      <test name="System.Net.NameResolution.PalTests.NameResolutionPalTests.GetHostByName_HostName" type="System.Net.NameResolution.PalTests.NameResolutionPalTests" method="GetHostByName_HostName" time="5.025076" result="Fail">
        <failure exception-type="System.Net.Internals.SocketExceptionFactory+ExtendedSocketException">
          <message><![CDATA[System.Net.Internals.SocketExceptionFactory+ExtendedSocketException : Device not configured]]></message>
          <stack-trace><![CDATA[   at System.Net.NameResolutionPal.GetHostByName(String hostName) in /private/tmp/corefx/src/System.Net.NameResolution/src/System/Net/NameResolutionPal.Unix.cs:line 151
   at System.Net.NameResolution.PalTests.NameResolutionPalTests.GetHostByName_HostName() in /private/tmp/corefx/src/System.Net.NameResolution/tests/PalTests/NameResolutionPalTests.cs:line 40]]></stack-trace>
        </failure>
      </test>

These two were a Device not configured exception in DNS resolution.

      <test name="System.Net.NameResolution.PalTests.NameResolutionPalTests.GetHostByName_HostName_GetHostByAddr" type="System.Net.NameResolution.PalTests.NameResolutionPalTests" method="GetHostByName_HostName_GetHostByAddr" time="0.084207" result="Pass" />
      <test name="System.Net.NameResolution.PalTests.NameResolutionPalTests.TryGetAddrInfo_HostName" type="System.Net.NameResolution.PalTests.NameResolutionPalTests" method="TryGetAddrInfo_HostName" time="5.010565" result="Fail">
        <failure exception-type="Xunit.Sdk.EqualException">
          <message><![CDATA[Assert.Equal() Failure\nExpected: Success\nActual:   HostNotFound]]></message>
          <stack-trace><![CDATA[   at System.Net.NameResolution.PalTests.NameResolutionPalTests.TryGetAddrInfo_HostName() in /private/tmp/corefx/src/System.Net.NameResolution/tests/PalTests/NameResolutionPalTests.cs:line 116]]></stack-trace>
        </failure>
      </test>

This one suggests there are no DNS records for my current hostname, which, testing with dig, does appear to be true.

[tarekgh]

will take a look at the globalization tests when have a chance. yes I can see the capitalization issue but I need to double check the data on MAC

[tarekgh]

will take a look at the Process failing too.

[karelz]

I wonder if this is some bad/weird machine setup causing the failures. We're running the tests in CI on Mac and on several dev Macs - they don't fail anywhere ...
Anyway, let's try to root cause at least one test failure, then hopefully we can make some conclusions ...

[tarekgh]

I confirmed seeing the failures on macOS 10.12.3. this is Sierra mac release which looks changed some stuff on it. I have fix for the globalization failure will try to submit a PR for it today. also looked at the Process failure and the problem looks there is some change that broke the assumption how we calculate the process start time (note that is not related to Time zones). I am looking more deeply on that.

will try to look at the networking failures too to know if there is easy fix or I have to get the networking guys take a look.

[karelz]

Thanks @tarekgh! Any idea why it slipped through our internal testing? Is it because we do not test on Sierra?

[tarekgh]

most likely we don't test on Sierra. is there a way can I get the CI configuration machine? I mean what MacOS version used in the runs?

CC @mmitche

[mmitche]

@tarekgh El Cap

[tarekgh]

thanks @mmitche. as expected :-)

[karelz]

@mmitche is there a plan to keep our Mac machines running on latest MacOS?

[mmitche]

@karelz I don't have a plan to upgrade currently. It's up to the .NET Core LT to decide what to do.