Runtime: PublicKeyTests.TestKey_RSA failure on Unix in CI

[stephentoub]

http://dotnet-ci.cloudapp.net/job/dotnet_corefx/job/centos7.1_release_tst_prtest/1959/console

17:10:15    System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA [FAIL]
17:10:15       Assert.Equal() Failure
17:10:15       Expected: Byte[] [232, 175, 92, 162, 32, ...]
17:10:15       Actual:   Byte[] [0, 0, 0, 0, 0, ...]
17:10:15       Stack Trace:
17:10:16             at System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA()

[ericeil]

Another failure, also on CentOS:
http://dotnet-ci.cloudapp.net/job/dotnet_corefx/job/centos7.1_release_tst_prtest/2647/consoleFull#-21371504001f1a4601-6aec-4fd5-b678-78d4389fd5e8

[stephentoub]

Again here:
http://dotnet-ci.cloudapp.net/job/dotnet_corefx/job/centos7.1_release_tst_prtest/2904/console

06:49:04    System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA [FAIL]
06:49:04       Assert.Equal() Failure
06:49:04       Expected: Byte[] [232, 175, 92, 162, 32, ...]
06:49:04       Actual:   Byte[] [0, 0, 0, 0, 0, ...]
06:49:04       Stack Trace:
06:49:04             at System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA()

[stephentoub]

Failed again here, but this time on OSX:
http://dotnet-ci.cloudapp.net/job/dotnet_corefx/job/osx_release_tst_prtest/2704/console

03:01:51    System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA [FAIL]
03:01:51       Assert.Equal() Failure
03:01:51       Expected: Byte[] [232, 175, 92, 162, 32, ...]
03:01:51       Actual:   Byte[] [0, 0, 0, 0, 0, ...]
03:01:51       Stack Trace:
03:01:51             at System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA()

[stephentoub]

Failed again:
http://dotnet-ci.cloudapp.net/job/dotnet_corefx/job/ubuntu_release_tst_prtest/4064/console

14:40:27    System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA [FAIL]
14:40:27       Assert.Equal() Failure
14:40:27       Expected: Byte[] [1, 0, 1]
14:40:27       Actual:   Byte[] []
14:40:27       Stack Trace:
14:40:28             at System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA()

[stephentoub]

I think we should investigate this for 1.0.0-rtm... it could potentially be a product bug.

[stephentoub]

This is still happening, e.g.
http://ci.dot.net/job/dotnet_corefx/job/master/job/opensuse42.1_release/142/
http://ci.dot.net/job/dotnet_corefx/job/master/job/osx_release/283/
https://ci.dot.net/job/dotnet_corefx/job/master/job/ubuntu14.04_release/451/
https://ci.dot.net/job/dotnet_corefx/job/master/job/ubuntu16.04_release/414/
https://ci.dot.net/job/dotnet_corefx/job/master/job/osx_release/483/

[danmosemsft]

@steveharter

[stephentoub]

Again here:
https://ci.dot.net/job/dotnet_corefx/job/master/job/osx_release_prtest/1146/consoleText

[danmosemsft]

@steveharter could you please take a look? this seems like a correctness issue, as well as CI impact.

@bartonjs

[JeremyKuhne]

This happens regularly- and I think it may also be causing seg faults sometimes.

[stephentoub]

Again here:
https://ci.dot.net/job/dotnet_corefx/job/master/job/centos7.1_release_prtest/2055/consoleText

[danmosemsft]

According to this it has failed 4 times in Dec/Jan

http://jdash.azurewebsites.net/builds/test?name=System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestKey_RSA&viewName=dotnet_corefx&pr=true&startDate=2016-12-01&limit=20 (check 'include PRs')

[danmosemsft]

@bartonjs could you comment? What is the next action? This seems likely to be a real product issue and potentially significant.

[bartonjs]

@danmosemsft The proposal I discussed with @steveharter was to make the test do something like

```c#
RSA rsa = cert.GetRSAPublicKey();
RSAParameters rsaParameters = rsa.ExportParameters(false);

if (!expectedModulus.SequenceEqual(rsaParameters.Modulus) ||
!expectedExponent.SequenceEqual(rsaParameters.Exponent)
{
rsaParameters = rsa.ExportParameters(false);

if (!expectedModulus.SequenceEqual(rsaParameters.Modulus) ||
    !expectedExponent.SequenceEqual(rsaParameters.Exponent)
{
    Assert.False(true, "Second call to ExportParameters produced valid data, but the first did not");
}

rsa = rsa.GetRSAPublicKey();
rsaParameters = rsa.ExportParameters(false);

if (!expectedModulus.SequenceEqual(rsaParameters.Modulus) ||
    !expectedExponent.SequenceEqual(rsaParameters.Exponent)
{
    Assert.False(true, "New key handle ExportParameters was successful, original key handle was not");
}    

Assert.False(true, "Key's busted");

}
```

(Though ensuring a) it compiles, and b) that the messages are all correct/useful)

[danmosemsft]

OK, good that it's not a product bug then. Do either of you have cycles to make this change?

[bartonjs]

OK, good that it's not a product bug then.

Well, we don't know that it is or isn't. This is just the good old "add logging to figure out what sort of problem we're facing", since it hasn't reproed for me under at least a million runs (not sarcastic; did a seq 1 1000000 launch loop, and it finished, having never failed).

[stephentoub]

Again here:
https://ci.dot.net/job/dotnet_corefx/job/master/job/centos7.1_release_prtest/2268/consoleText

System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.TestPublicKey_Key_RSA [FAIL]
        Assert.Equal() Failure
        Expected: Byte[] [232, 175, 92, 162, 32, ...]
        Actual:   Byte[] [0, 0, 0, 0, 0, ...]
        Stack Trace:
           /mnt/resource/j/workspace/dotnet_corefx/master/centos7.1_release_prtest/src/System.Security.Cryptography.X509Certificates/tests/PublicKeyTests.cs(212,0): at System.Security.Cryptography.X509Certificates.Tests.PublicKeyTests.VerifyKey_RSA(RSA rsa)

[danmosemsft]

Alright, I'll add this since nobody is biting. :)

[steveharter]

I'll start on this later today.

[danmosemsft]

Steve I already added the logging. Thanks!

[danmosemsft]

@jiangzeng @Jiayili1 when this test fails again please let me know so we can grab the extra logging that 's now added. thanks.

[danmosemsft]

Closing to make sure this gets opened when there's logging.

[mellinoe]

I hit this again:

https://ci.dot.net/job/dotnet_corefx/job/release_2.0.0/job/ubuntu14.04_release_prtest/27/consoleText

[ViktorHofer]

@mellinoe looks like a different test

[bartonjs]

@ViktorHofer Yes, its a different test, but it's the same problem.

[ianhays]

@bartonjs think we should add the extra validation Dan added to this test as well? It would of course be a bit different since we're loading xml and not using an x509 cert, but the validation would be mostly the same.

[bartonjs]

@ianhays I sort of wonder if we want to do something weird and put it as self-debugging code (in #if DEBUG) in the product code itself.

If it's about to export Exponent == all zeros or Modulus == all zeros, and it's in debug, either do the retry and throw a "it's a miracle, retry worked!" or "totes seems borked, dude..." exception.

Or if it catches it to just crashdump so we can see what happened.... if we have that power.

[steveharter]

@bartonjs I think the product-wise DEBUG option would find the issue quicker, and help with a fix especially if we need to add re-try logic to certain OpenSsl calls.

[bartonjs]

@ianhays Do you want to take care of moving the retry into a #if DEBUG section? Since we don't know what "wrong" means we'll just have to check for all zeros.

There are a couple places that could benefit:

• ExtractBignum between when the fixed block ends and it returns the buffer. But there the logic would need to ensure that we weren't actually trying to export the number 0. So `if (compactSize > 1 && buf[offset] == 0) DoSomethingDebuggyLikeCrashdump();
• ExportRsaParameters. Modulus can't start with a 0, Exponent can't start with a 0. None of the private parameters can be 0 (but they can start with 0. Except maybe D, I'm having trouble projecting that one in my head).

[ianhays]

Yeah, I'll take this one.

[steveharter]

FWIW here's Jenkins history since May 2016 including the release branch. I can't say whether each of these failed for the same reason this issue is tracking, since that level of history isn't available.

Pretty much every flavor of Linux + Mac.

dotnet_corefx/master/rhel7.2_release_tst 497    Azure0527143620     05/28 01:05 AM      0
dotnet_corefx/master/ubuntu16.04_release 149    Azure0622234024     06/23 07:01 AM      0
dotnet_corefx/master/opensuse13.2_release 281   Azure0713174021     07/14 12:44 AM      0
dotnet_corefx/master/osx_release 753    dci-macpro-09   07/16 04:46 PM      0
dotnet_corefx/master/centos7.1_release 502  Azure0720100957     07/20 10:12 PM      0
dotnet_corefx/master/fedora23_release 326   Azure0722161849     07/23 01:46 AM      0
dotnet_corefx/master/centos7.1_release 545  Azure0726132739     07/26 09:05 PM      0
dotnet_corefx/master/osx_release 830    dci-macpro-08   07/27 05:42 PM      0
dotnet_corefx/dev_cms_unix/fedora23_release 16  Azure0808092329     08/08 10:21 PM      0
dotnet_corefx/master/debian8.4_release 409  Azure0809114259     08/09 08:37 PM      0
dotnet_corefx/master/osx_release 922    dci-macpro-09   08/17 12:36 AM      0
dotnet_corefx/master/ubuntu16.04_release 501    Azure0819150126     08/19 10:03 PM      0
dotnet_corefx/master/debian8.4_release 535  Azure0826140906     08/26 09:12 PM      0
dotnet_corefx/master/centos7.1_release 843  Azure0906165803     09/07 02:34 AM      0
dotnet_corefx/master/ubuntu16.10_release 130    Azure0930064247     09/30 07:17 PM      0
dotnet_corefx/master/opensuse42.1_release 142   Azure1001085143     10/01 03:55 PM      0
dotnet_corefx/master/osx_release 283    dci-macpro-09   10/06 12:30 AM      0
dotnet_corefx/master/ubuntu14.04_release 451    ubuntu1404-20160211-1-1013480   10/17 06:07 PM      0
dotnet_corefx/master/ubuntu16.04_release 414    ubuntu1604-20160803-17214711    10/18 01:00 AM      0
dotnet_corefx/master/osx_release 483    dci-macpro-09   10/19 06:24 AM      0
dotnet_corefx/master/ubuntu14.04_release-hangdebug 73   ubuntu1404-20160211-1-7e02a0    10/22 08:10 AM      0
dotnet_corefx/master/outerloop_ubuntu14.04_release 43   Azure1023104012     10/23 05:42 PM      0
dotnet_corefx/master/ubuntu14.04_release-hangdebug 97   ubuntu1404-20160211-1-bac250    10/23 08:10 AM      0
dotnet_corefx/master/debian8.4_release 436  deb84-20160623-174930   10/24 02:58 AM      0
dotnet_corefx/master/ubuntu14.04_release-hangdebug 165  ubuntu1404-20160211-1-8de947    10/26 05:10 AM      0
dotnet_corefx/master/centos7.1_release 563  centos71-20160929-cae7d0    10/26 06:59 PM      0
dotnet_corefx/master/ubuntu14.04_release 686    ubuntu1404-20160211-1-eb1c90    11/01 07:28 PM      0
dotnet_corefx/master/fedora24_release 22    fedora24-20161024-71ea70    11/03 10:38 PM      0
dotnet_corefx/master/fedora23_release 608   fedora23-20160622-f01740    11/03 06:10 PM      0
dotnet_corefx/release_1.1.0/rhel7.2_release 26  rhel72-20160211-c51390  12/28 10:53 PM      0
dotnet_corefx/release_1.1.0/outerloop_osx_release 17    dci-macpro-03   12/29 08:15 PM      0
dotnet_corefx/release_1.1.0/debian8.4_release 32    deb84-20160623-694230   01/03 01:39 PM      0
dotnet_corefx/release_1.1.0/outerloop_ubuntu16.04_release 30    ubuntu1604-20160510-outereb0800     01/07 05:16 AM      0
dotnet_corefx/release_1.1.0/outerloop_osx_release 33    dci-macpro-02   01/16 08:16 PM      0
dotnet_corefx/release_1.0.0/opensuse13.2_release 59     suse132-20160315-323e30     01/19 02:07 PM      0
dotnet_corefx/release_1.0.0/osx_release 67  dci-macpro-02   01/19 03:04 AM      0
dotnet_corefx/release_1.0.0/outerloop_osx_release 34    dci-macpro-02   01/22 04:29 AM      0
dotnet_corefx/release_1.1.0/ubuntu14.04_release 133     ubuntu1404-20160211-1-24f8f1    03/10 05:19 PM      0

[karelz]

All failures are in release builds :(

[steveharter]

Good catch @karelz. Also I updated the list to further back - still only release builds

[bartonjs]

Yeah, I hadn't noticed that. Good eye, Karel. Hmm.

[karelz]

Could we add a hack to crash hard when env. var. is set and it happens? (and set the env. var. in Jenkins & Helix)

[karelz]

BTW: If chasing down this bug means also updating 1.x, I'd support it

[ianhays]

@steveharter does the jdash report accurately show failures from PRs? I looked to JDash for the failures linked in this issue, but they appear to be missing. The last non-release branch failure on jdash occurred on 11/03, but Stephen linked failures from January above.

[steveharter]

@ianhays I also included PRs in my query, and none showed up, so yes something is amiss in the data.

[bartonjs]

I'm like 99% sure I just found the missing GC.KeepAlive and the confusing scenario that bound it all up.

Thanks @karelz for noticing the release-only, and @steveharter for getting a stable repro with that knowledge.

[karelz]

Congrats on chasing down the issue after 1+ year of rare, yet annoying, occurrences! -- Great work! Thanks to everyone helping to catch it.

BTW: @danmosemsft is now tracking down why we didn't run all tests under GCStress=3 on Release mode as we planned. We will finish that off as well.