Test failure System.IO.Tests.FileInfo_SymbolicLinks.CreateSymbolicLink_PathToTarget_RelativeToLinkPath

[v-wenyuxu]

Run: runtime-coreclr libraries-jitstress 20220821.1

Failed test:

net7.0-windows-Release-x64-CoreCLR_checked-zapdisable-Windows.10.Amd64.Open

- System.IO.Tests.FileInfo_SymbolicLinks.CreateSymbolicLink_PathToTarget_RelativeToLinkPath
- System.IO.Tests.FileInfo_OpenSpecial.FileShareOpen_Inheritable
- System.IO.Tests.FileStream_ctor_str_fm_fa_fs_buffer_async.FileShareOpen_Inheritable

Error message:

Half-way through waiting for remote process.
Memory load: 11

Image Name                     PID Services

========================= ======== ============================================
svchost.exe                    776 BrokerInfrastructure, DcomLaunch, LSM,

PlugPlay, Power, SystemEventsBroker

svchost.exe                    836 RpcEptMapper, RpcSs

svchost.exe                    964 TermService

svchost.exe                   1008 Appinfo, CertPropSvc, gpsvc, iphlpsvc,

lfsvc, ProfSvc, sacsvr, Schedule, SENS,

SessionEnv, ShellHWDetection, Themes,

UserManager, Winmgmt, WpnService, wuauserv

svchost.exe                    320 Dhcp, EventLog, lmhosts, TimeBrokerSvc,

vmictimesync

svchost.exe                    448 NcbService, PcaSvc, TrkWks, UALSVC,

UmRdpService, vmickvpexchange,

vmicshutdown, WdiSystemHost

svchost.exe                    396 CDPSvc, EventSystem, FontCache, netprofm,

nsi, W32Time, WinHttpAutoProxySvc

svchost.exe                   1072 BFE, CoreMessagingRegistrar, DPS, MpsSvc,

pla

svchost.exe                   1172 CryptSvc, Dnscache, LanmanWorkstation,

NlaSvc, WinRM

svchost.exe                   1212 vmicheartbeat

svchost.exe                   1440 Wcmsvc

svchost.exe                   1988 DiagTrack

svchost.exe                   2020 LanmanServer

svchost.exe                   2044 StateRepository, tiledatamodelsvc

svchost.exe                   1816 W3SVC, WAS

svchost.exe                   1980 AppHostSvc

svchost.exe                   3284 CDPUserSvc_49b41, OneSyncSvc_49b41

Timed out at 8/21/2022 8:42:34 AM after 60000ms waiting for remote process.
Wrote mini dump to: C:\h\w\B6C109DB\w\AE7209A3\uploads\4060.2wmwjjv3.xsj.dmp
Process ID: 4060
Handle: 712
Name:


Stack trace
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing) in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 224
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs:line 64

[dotnet-issue-labeler]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[ghost]

Tagging subscribers to this area: @JulieLeeMSFT, @jakobbotsch
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Run: runtime-coreclr libraries-jitstress 20220821.1

Failed test:

net7.0-windows-Release-x64-CoreCLR_checked-zapdisable-Windows.10.Amd64.Open

- System.IO.Tests.FileInfo_SymbolicLinks.CreateSymbolicLink_PathToTarget_RelativeToLinkPath
- System.IO.Tests.FileInfo_OpenSpecial.FileShareOpen_Inheritable
- System.IO.Tests.FileStream_ctor_str_fm_fa_fs_buffer_async.FileShareOpen_Inheritable

Error message:

Half-way through waiting for remote process.
Memory load: 11

Image Name                     PID Services

========================= ======== ============================================
svchost.exe                    776 BrokerInfrastructure, DcomLaunch, LSM,

PlugPlay, Power, SystemEventsBroker

svchost.exe                    836 RpcEptMapper, RpcSs

svchost.exe                    964 TermService

svchost.exe                   1008 Appinfo, CertPropSvc, gpsvc, iphlpsvc,

lfsvc, ProfSvc, sacsvr, Schedule, SENS,

SessionEnv, ShellHWDetection, Themes,

UserManager, Winmgmt, WpnService, wuauserv

svchost.exe                    320 Dhcp, EventLog, lmhosts, TimeBrokerSvc,

vmictimesync

svchost.exe                    448 NcbService, PcaSvc, TrkWks, UALSVC,

UmRdpService, vmickvpexchange,

vmicshutdown, WdiSystemHost

svchost.exe                    396 CDPSvc, EventSystem, FontCache, netprofm,

nsi, W32Time, WinHttpAutoProxySvc

svchost.exe                   1072 BFE, CoreMessagingRegistrar, DPS, MpsSvc,

pla

svchost.exe                   1172 CryptSvc, Dnscache, LanmanWorkstation,

NlaSvc, WinRM

svchost.exe                   1212 vmicheartbeat

svchost.exe                   1440 Wcmsvc

svchost.exe                   1988 DiagTrack

svchost.exe                   2020 LanmanServer

svchost.exe                   2044 StateRepository, tiledatamodelsvc

svchost.exe                   1816 W3SVC, WAS

svchost.exe                   1980 AppHostSvc

svchost.exe                   3284 CDPUserSvc_49b41, OneSyncSvc_49b41

Timed out at 8/21/2022 8:42:34 AM after 60000ms waiting for remote process.
Wrote mini dump to: C:\h\w\B6C109DB\w\AE7209A3\uploads\4060.2wmwjjv3.xsj.dmp
Process ID: 4060
Handle: 712
Name:


Stack trace
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing) in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 224
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs:line 64

Author:	v-wenyuxu
Assignees:	-
Labels:	os-windows, JitStress, arch-x64, area-CodeGen-coreclr, untriaged, blocking-clean-ci-optional
Milestone:	-

[AndyAyersMS]

Timed out at 8/21/2022 8:42:34 AM after 60000ms waiting for remote process.

Likely nothing to do with codegen.

[JulieLeeMSFT]

Timed out at 8/21/2022 8:42:34 AM after 60000ms waiting for remote process.

Likely nothing to do with codegen.

@jeffschwMSFT, who do we need to assign this to? @agocke is out.

[ghost]

Tagging subscribers to this area: @dotnet/area-system-io
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Run: runtime-coreclr libraries-jitstress 20220821.1

Failed test:

net7.0-windows-Release-x64-CoreCLR_checked-zapdisable-Windows.10.Amd64.Open

- System.IO.Tests.FileInfo_SymbolicLinks.CreateSymbolicLink_PathToTarget_RelativeToLinkPath
- System.IO.Tests.FileInfo_OpenSpecial.FileShareOpen_Inheritable
- System.IO.Tests.FileStream_ctor_str_fm_fa_fs_buffer_async.FileShareOpen_Inheritable

Error message:

Half-way through waiting for remote process.
Memory load: 11

Image Name                     PID Services

========================= ======== ============================================
svchost.exe                    776 BrokerInfrastructure, DcomLaunch, LSM,

PlugPlay, Power, SystemEventsBroker

svchost.exe                    836 RpcEptMapper, RpcSs

svchost.exe                    964 TermService

svchost.exe                   1008 Appinfo, CertPropSvc, gpsvc, iphlpsvc,

lfsvc, ProfSvc, sacsvr, Schedule, SENS,

SessionEnv, ShellHWDetection, Themes,

UserManager, Winmgmt, WpnService, wuauserv

svchost.exe                    320 Dhcp, EventLog, lmhosts, TimeBrokerSvc,

vmictimesync

svchost.exe                    448 NcbService, PcaSvc, TrkWks, UALSVC,

UmRdpService, vmickvpexchange,

vmicshutdown, WdiSystemHost

svchost.exe                    396 CDPSvc, EventSystem, FontCache, netprofm,

nsi, W32Time, WinHttpAutoProxySvc

svchost.exe                   1072 BFE, CoreMessagingRegistrar, DPS, MpsSvc,

pla

svchost.exe                   1172 CryptSvc, Dnscache, LanmanWorkstation,

NlaSvc, WinRM

svchost.exe                   1212 vmicheartbeat

svchost.exe                   1440 Wcmsvc

svchost.exe                   1988 DiagTrack

svchost.exe                   2020 LanmanServer

svchost.exe                   2044 StateRepository, tiledatamodelsvc

svchost.exe                   1816 W3SVC, WAS

svchost.exe                   1980 AppHostSvc

svchost.exe                   3284 CDPUserSvc_49b41, OneSyncSvc_49b41

Timed out at 8/21/2022 8:42:34 AM after 60000ms waiting for remote process.
Wrote mini dump to: C:\h\w\B6C109DB\w\AE7209A3\uploads\4060.2wmwjjv3.xsj.dmp
Process ID: 4060
Handle: 712
Name:


Stack trace
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing) in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 224
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs:line 64

Author:	v-wenyuxu
Assignees:	-
Labels:	area-System.IO, os-windows, JitStress, arch-x64, untriaged, blocking-clean-ci-optional
Milestone:	-

[danmoseley]

IO owners. Would need to look at dump.

[jozkee]

All the faulting tests are using RemoteExecutor, and the method where the dump occurs is System.Environmet.get_OSVersion() (I think?).
Some things that I think are interesting from the dumps:

Method Name:          System.Environment.get_OSVersion()

SYMBOL_NAME:  Microsoft_DotNet_RemoteExecutor+8473

MODULE_NAME: Microsoft_DotNet_RemoteExecutor

IMAGE_NAME:  Microsoft.DotNet.RemoteExecutor.dll

FAILURE_BUCKET_ID:  BREAKPOINT_80000003_Microsoft.DotNet.RemoteExecutor.dll!Unknown

I'm unable to find the symbols for RemoteExecutor so that might give me more info about the error.

[danmoseley]

Did you get the helix payload? It has remote executor binary but not symbols?

Can you get a native callstack? Sometimes it is necessary to get several dumps and look for a pattern.

[danmoseley]

It doesn't contain the dll nor the pdb.

Since the payload is what is executed , that is hard to explain

[jozkee]

Actually, ignoring the dumps, this is just the RemoteExecutor timing out after 60s, Can we use a larger timeout on JitStress runs?

[danmoseley]

I think you can't assume that the test isn't hung.

@BruceForstall what environment variables should @jozkee set locally to get the test to run as slow as the slowest jitstress run that would run this test?

@jozkee if you can verify that way that it's merely slow, I suppose we could make a change here to increase the timeout (eg x3) when DOTNET_JitStress=1 or whatever.

[BruceForstall]

In the console log, you can see this failure was run with:

set COMPlus_TieredCompilation=0
set COMPlus_ReadyToRun=0
set COMPlus_ZapDisable=1

The 2nd one means more JIT compilation.

Setting COMPlus_JITMinOpts=1 would run much slower generated code.

[jozkee]

I ran it locally with the jitstress variables but they didn't made the test execution slower at all:

Baseline:

  === TEST EXECUTION SUMMARY ===
     System.IO.FileSystem.Tests  Total: 8680, Errors: 0, Failed: 0, Skipped: 57, Time: 10.553s

With set COMPlus_TieredCompilation=0 set COMPlus_ReadyToRun=0 & set COMPlus_ZapDisable=1

  === TEST EXECUTION SUMMARY ===
     System.IO.FileSystem.Tests  Total: 8680, Errors: 0, Failed: 0, Skipped: 57, Time: 10.319s

With above set + COMPlus_JITMinOpts=1

  === TEST EXECUTION SUMMARY ===
     System.IO.FileSystem.Tests  Total: 8680, Errors: 0, Failed: 0, Skipped: 57, Time: 10.319s

[jozkee]

FWIW, I queried for "Half-way through waiting for remote process." issues and found the following.

Failures with Jitstress and remotexecutor
#48798 (comment)
#44060

Failures with Jitstress and remotexecutor that were closed:
#71243
#67217

Similar but not jitstress:
#70674
#44037
#38998
#69231
#68034

Whatever the root cause is, its probably the same for this list of issues.

[danmoseley]

All it means is "a test hung" or "a test was running very slowly". You can't conclude anything else without a dump or repro.

[AndyAyersMS]

In my experience the CI machines are often heavily loaded, and this leads them to unusual interleaving and delay in test execution that can be hard to repro locally.

You might try loading down your machine when running the tests, either via some explicit stress program (stress on linux, say) or by running a couple copies of the test concurrently, or by kicking off a build of the repo while the tests are running.

[jozkee]

No repro since May #90041 (comment), will close for now.