Test failure: System.Runtime.Tests.ProfileOptimizationTest/ProfileOptimization_CheckFileExists

[ghost]

Opened on behalf of @Sunny-pu

The test System.Runtime.Tests.ProfileOptimizationTest/ProfileOptimization_CheckFileExists has failed.

Assert.True() Failure
Expected: True
Actual: False

    Stack Trace:

       at System.Runtime.Tests.ProfileOptimizationTest.ProfileOptimization_CheckFileExists() in /root/corefx-1952310/src/System.Runtime.Extensions/tests/System/Runtime/ProfileOptimization.netcoreapp.cs:line 26

Build : 3.0 - 20180816.01 (Core Tests)
Failing configurations:

• RedHat.69.Amd64-x64
  • Release

Details:https://mc.dot.net/#/product/netcore/30/source/official~2Fcorefx~2Fmaster~2F/type/test~2Ffunctional~2Fcli~2F/build/20180816.01/workItem/System.Runtime.Extensions.Tests/analysis/xunit/System.Runtime.Tests.ProfileOptimizationTest~2FProfileOptimization_CheckFileExists

[danmoseley]

@MarcoRossignoli @brianrob if profiling failed in this test for some reason, would it have failed before this point, or been silent? Or maybe we just need to sleep and retry a bit because profiling hasn't started quick enough?

[MarcoRossignoli]

@brianrob @danmosemsft strange...first time i see that...is this first fail?However...if you agree i could add 5 second sleep between StartProfile and return...and some retry on Exists, do you agree?

[danmoseley]

@MarcoRossignoli yes a sleep/retry would be good, but please write it such that it does not sleep in the normal case, only in the failure case.

[danmoseley]

@MarcoRossignoli here's a hit, again on RedHat69 release

https://mc.dot.net/#/product/netcore/30/source/official~2Fcorefx~2Fmaster~2F/type/test~2Ffunctional~2Fcli~2F/build/20180917.04/workItem/System.Runtime.Extensions.Tests/wilogs

2018-09-17 08:49:36,041: INFO: proc(55): run_and_log_output: Output: �[m�[31;1m    System.Runtime.Tests.ProfileOptimizationTest.ProfileOptimization_CheckFileExists [FAIL]
2018-09-17 08:49:36,042: INFO: proc(55): run_and_log_output: Output: �[m�[37m      Assert.True() Failure
2018-09-17 08:49:36,042: INFO: proc(55): run_and_log_output: Output: �[m�[37m      Expected: True
2018-09-17 08:49:36,042: INFO: proc(55): run_and_log_output: Output: �[m�[37m      Actual:   False
2018-09-17 08:49:36,043: INFO: proc(55): run_and_log_output: Output: �[m�[30;1m      Stack Trace:
2018-09-17 08:49:36,050: INFO: proc(55): run_and_log_output: Output: �[m�[37m        /root/corefx-2036320/src/System.Runtime.Extensions/tests/System/Runtime/ProfileOptimization.netcoreapp.cs(41,0): at System.Runtime.Tests.ProfileOptimizationTest.ProfileOptimization_CheckFileExists()
2018-09-17 08:49:36,051: INFO: proc(55): run_and_log_output: Output: �[m�[30;1m      Output:
2018-09-17 08:49:36,051: INFO: proc(55): run_and_log_output: Output: �[m�[37m        We'll test write permission on path 'dfyd322r.lhn'
2018-09-17 08:49:36,809: INFO: proc(55): run_and_log_output: Output: �[m�[37m  Finished:    System.Runtime.Extensions.Tests

I guess this means that it successfully wrote "42" to the file

The two asserts are

            Assert.True(fileInfo.Exists);
             Assert.True(fileInfo.Length > 0);

The previous failure line was the first one, now it's the second one. Line numbers can be one-off for whatever reason (this is release) so it's not clear which assert fired.

It might be worth logging a message after successfully writing to the file, and adding strings to these two asserts so we'll know for sure which is firing.

[danmoseley]

I'll update the test

[rmkerr]

I think this is the last consistently occurring failure in the daily test runs. Every run on RedHat 6.9 fails. RedHat 6.9 is interesting because it's only test leg that runs on a single core VM, but I wasn't able to repro running with -maxthreads 1 on my machine.

For reference, here's the output from the latest failure:

2018-10-09 08:48:04,657: INFO: proc(55): run_and_log_output: Output: �[m�[31;1m    System.Runtime.Tests.ProfileOptimizationTest.ProfileOptimization_CheckFileExists [FAIL]
2018-10-09 08:48:04,658: INFO: proc(55): run_and_log_output: Output: �[m�[37m      'ProfileOptimization_CheckFileExists_18_0da21f98' does not exist
2018-10-09 08:48:04,658: INFO: proc(55): run_and_log_output: Output: �[m�[37m      Expected: True
2018-10-09 08:48:04,658: INFO: proc(55): run_and_log_output: Output: �[m�[37m      Actual:   False
2018-10-09 08:48:04,659: INFO: proc(55): run_and_log_output: Output: �[m�[30;1m      Stack Trace:
2018-10-09 08:48:04,668: INFO: proc(55): run_and_log_output: Output: �[m�[37m        /root/corefx-2100476/src/System.Runtime.Extensions/tests/System/Runtime/ProfileOptimization.netcoreapp.cs(49,0): at System.Runtime.Tests.ProfileOptimizationTest.ProfileOptimization_CheckFileExists()

[MarcoRossignoli]

https://github.com/dotnet/corefx/blob/master/src/System.Runtime.Extensions/tests/System/Runtime/ProfileOptimization.netcoreapp.cs#L48
@danmosemsft wait for 5 seconds not seem enough @brianrob do you have some idea?

[danmoseley]

Until we know, we should disable this test against this issue number.

[danmoseley]

@brianrob is it possible the API is not closing the file synchronously?

[brianrob]

Adding @noahfalk who owns this feature now. The profile should be closed by the time the process exits. Runtime shutdown gets blocked to write the file out. If it doesn't exist by the time the process is actually gone then it's possible that there is a delay in the file actually being written out to disk, but I would expect the OS to handle this if you ask to open the file.

[danmoseley]

Could be a Redhat quirk...

[noahfalk]

I used to own it, adding @kouvel who is the current owner