CoreCLR initialization failures logging #78790

janvorli · 2022-11-24T00:34:52Z

This change adds detecting and logging of failures during coreclr initialization. For logging, it uses a new host API coreclr_set_error_writer to register a callback to report the errors to the host. The hosts have support for optional usage of this API so that they can work with older runtime versions as well.

The logging checks and reports failures with:

System.Private.CoreLib.dll
GC initialization
JIT initialization
libSystem.Native.so/dylib on Unix

The logging messages should allow customers to self-diagnose the issues causing the failures.

This change adds detecting and logging of failures during coreclr initialization. For logging, it uses a new host API `coreclr_set_error_writer` to register a callback to report the errors to the host. The hosts have support for optional usage of this API so that they can work with older runtime versions as well. The logging checks and reports failures with: * System.Private.CoreLib.dll * GC initialization * JIT initialization * libSystem.Native.so/dylib on Unix The logging messages should allow customers to self-diagnose the issues causing the failures.

janvorli · 2022-11-24T00:38:41Z

Here are some examples of the error logs:

Missing SPC file

Failed to load System.Private.CoreLib.dll (error code 0x80070057)
Path: 'F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll'

Could not load file or assembly 'F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll'. The parameter is incorrect. (0x80070057 (E_INVALIDARG))

Another assembly instead of SPC

Failed to load System.Private.CoreLib.dll (error code 0x80131522)
Path: 'F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll'

Could not load type 'System.Object' from assembly 'System.ObjectModel, Version=7.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'.

Text file instead of SPC

Failed to load System.Private.CoreLib.dll (error code 0x80131018)
Path: 'F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll'

Could not load file or assembly 'F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll'. The module was expected to contain an assembly manifest. (0x80131018 (COR_E_ASSEMBLYEXPECTED))

Wrong version of SPC (x86)

Failed to load System.Private.CoreLib.dll (error code 0x8007000B)
Path: 'F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll'

Could not load file or assembly 'F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll'. An attempt was made to load a program with an incorrect format. (0x8007000B (COR_E_BADIMAGEFORMAT))

Wrong version of SPC (x64 from 3.1):

Failed to load System.Private.CoreLib.dll (error code 0x80131522)
Path: 'F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll'

Could not load type 'System.Runtime.CompilerServices.CastHelpers' from assembly 'System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e'.

OOM

Failed to load System.Private.CoreLib.dll (error code 0x8007000E)
Path:
F:\git\runtime8\artifacts\tests\coreclr\windows.x64.Debug\Tests\Core_Root\System.Private.CoreLib.dll
Error message:
Out Of Memory

Wrong setting of GC log file

GC: Cannot create log file
GC heap initialization failed with error 0x80004005

jkotas · 2022-11-24T00:44:39Z

src/coreclr/vm/ceemain.cpp

@@ -947,6 +950,21 @@ void EEStartupHelper()
                                                g_MiniMetaDataBuffMaxSize, MEM_COMMIT, PAGE_READWRITE);
 #endif // FEATURE_MINIMETADATA_IN_TRIAGEDUMPS

+#ifdef TARGET_UNIX
+        // Preload the libSystem.Native.so/dylib to detect possible problems with loading it early


Is this going to work for singlefilehost?

Ah, singlefilehost should have been excluded here

jkotas · 2022-11-24T00:49:06Z

Missing SPC file

Where is the invalid arg comming from in this case? Would it be feasible to change it to file not found?

AaronRobinsonMSFT

I like the work here a lot.

src/coreclr/hosts/corerun/corerun.cpp

src/coreclr/vm/codeman.cpp

janvorli · 2022-11-24T14:34:29Z

Where is the invalid arg coming from in this case? Would it be feasible to change it to file not found?

It comes from here:

runtime/src/coreclr/binder/utils.cpp

Line 202 in 89cfbfd

GO_WITH_HRESULT(E_INVALIDARG);

When the S.P.C. is not found at the expected location, corerun tries to find it in the TPA list. To iterate over the list, it calls the GetNextTPAPath with dllOnly argument set to true. The E_INVALIDARG is returned because it comes to the corerun.exe on the TPA list. The behavior of the iteration is kind of weird, as it stops iterating over the list. I would expect it to skip non-dll entries instead in this case.
The iteration loop is here:

runtime/src/coreclr/binder/assemblybindercommon.cpp

Lines 297 to 315 in 89cfbfd

    
           for (SString::Iterator i = sTrustedPlatformAssemblies.Begin(); i != sTrustedPlatformAssemblies.End(); ) 
        
           { 
        
               SString fileName; 
        
               SString simpleName; 
        
               bool isNativeImage = false; 
        
               HRESULT pathResult = S_OK; 
        
               IF_FAIL_GO(pathResult = GetNextTPAPath(sTrustedPlatformAssemblies, i, /*dllOnly*/ true, fileName, simpleName, isNativeImage)); 
        
               if (pathResult == S_FALSE) 
        
               { 
        
                   break; 
        
               } 
        
               if (simpleName.EqualsCaseInsensitive(sCoreLibSimpleName)) 
        
               { 
        
                   sCoreLib = fileName; 
        
                   found = true; 
        
                   break; 
        
               } 
        
           }

* revert the try_get_export to not to have the isOptional argument * Unify the error logging in JIT loading to single variadic macro * Also fixes Unix build, the code in gcenv.unix.cpp cannot use the GCToEEInterface

jkotas · 2022-11-24T16:12:14Z

I would expect it to skip non-dll entries instead in this case.

Yes, I agree. (A separate question is why we need to be looking for CoreLib in so many places.)

jkotas · 2022-11-24T19:05:32Z

src/coreclr/vm/ceemain.cpp

@@ -947,6 +950,29 @@ void EEStartupHelper()
                                                g_MiniMetaDataBuffMaxSize, MEM_COMMIT, PAGE_READWRITE);
 #endif // FEATURE_MINIMETADATA_IN_TRIAGEDUMPS

+#ifdef TARGET_UNIX
+        // Check if the current code is executing in the single file host or in libcoreclr.so. The libSystem.Native is linked


Would it be better to just check if (!g_coreclr_embedded)?

I was looking for a check like that and have failed to locate this one :-)

I think you could also use the CORECLR_EMBEDDED define?

Ah, nice. I have not noticed that the ceemain.cpp is one of the few files that are compiled separately for single file host and libcoreclr.so.

@elinor-fung I have found that when S.P.C. is bundled, this NativeLibrary::LoadLibraryByName call doesn't work as the S.P.C. doesn't exist in the filesystem, just in the bundle. This causes e.g. the
Microsoft.NET.HostModel.Tests.BundleAndRun.TestWithRelativePaths test to fail.
Do I need to pass something else than SystemDomain::SystemAssembly() to NativeLibrary::LoadLibraryByName to make it work?

Ah, it seems I should pass in the DLLIMPORTSEARCHPATH_ASSEMBLYDIRECTORY.

The problem was actually different, in the EEStartupHelper, the native dll search paths from the properties passed by the host are not set yet. Moving the check to the end of the CreateAppDomainWithManager resolved the issue.

Sigh, yet one more host test failing.

I think that might be a variation of #75387? The case that is failing uses an extraction path that has a backslash on Unix and loading native libraries in PAL_LoadLibraryDirect goes through FILEDosToUnixPathA.

Ah, right, running it locally with the FILEDosToUnixPathA modified to be dummy fixed the issue. There was one more mono related issue that I've fixed, but now it seems fine.

janvorli · 2022-12-02T13:23:05Z

@jkotas, @AaronRobinsonMSFT the CI tests have passed except for one known issue and one unrelated issue. I believe I've addressed your feedback. Can you please take another look?

jkotas · 2022-12-02T14:13:58Z

Could you please make the message for missing CoreLib better (file not found instead of invalid arg)?

janvorli · 2022-12-05T23:21:31Z

@jkotas I've fixed that in the last commit.

jkotas

LGTM. Thank you!

vitek-karas · 2022-12-06T10:37:44Z

src/coreclr/dlls/mscoree/exports.cpp

+// Parameters:
+//  errorWriter             - callback that will be called for each line of the error info
+//                          - passing in NULL removes a callback that was previously set
+//


We should probably add that the callback can be called from any thread and thus must be thread safe.

It is not the case at the moment, it is always called from the thread running the initialization. Do you mean that we should add that comment to make it possible if we ever needed that?

Didn't realize we don't need it currently. But I would add it anyway... it's really easy to forget about this and it could break in really weird ways (the current host implementation is thread safe fortunately).

janvorli · 2022-12-06T23:20:22Z

The AllSubsets_Mono_LLVMFullAot_RuntimeTests llvmfullaot legs for x64 and arm64 are failing due to a sigsegv after I've pushed the fix for the error code. I don't see how that could have introduced such issue and I am unable to repro it on my local Ubuntu 21.04. Trying to repro in the centos 7 container that the lab uses.

MichalStrehovsky · 2022-12-06T23:57:20Z

The AllSubsets_Mono_LLVMFullAot_RuntimeTests llvmfullaot legs for x64 and arm64 are failing due to a sigsegv after I've pushed the fix for the error code. I don't see how that could have introduced such issue and I am unable to repro it on my local Ubuntu 21.04. Trying to repro in the centos 7 container that the lab uses.

I think you're hitting #78580 (comment) and it's not your PR.

janvorli · 2022-12-06T23:59:51Z

@MichalStrehovsky ah, great, thank you for letting me know!

janvorli added the area-VM-coreclr label Nov 24, 2022

janvorli added this to the 8.0.0 milestone Nov 24, 2022

janvorli requested review from cshung, jkotas, vitek-karas and AaronRobinsonMSFT November 24, 2022 00:34

janvorli requested a review from MichalStrehovsky as a code owner November 24, 2022 00:34

janvorli self-assigned this Nov 24, 2022

AaronRobinsonMSFT requested a review from elinor-fung November 24, 2022 00:39

jkotas reviewed Nov 24, 2022

View reviewed changes

AaronRobinsonMSFT reviewed Nov 24, 2022

View reviewed changes

Reflect PR feedback and a bit of cleanup

bd8dc22

* revert the try_get_export to not to have the isOptional argument * Unify the error logging in JIT loading to single variadic macro * Also fixes Unix build, the code in gcenv.unix.cpp cannot use the GCToEEInterface

Add single file host detection

7e330b5

jkotas reviewed Nov 24, 2022

View reviewed changes

runfoapp bot mentioned this pull request Nov 24, 2022

Infra improvements for Helix #68176

Closed

build-analysis bot mentioned this pull request Nov 24, 2022

CI build failure: Build MacCatalyst x64 Release AllSubsets_Mono - XcodeBuildApp task failed unexpectedly - Could not find System.Runtime.Tests.app #78778

Closed

Fix libSystem.Native check location

45e27b1

build-analysis bot mentioned this pull request Nov 26, 2022

System.IO.Pipes.Tests.NamedPipeTest_Specific.ClientConnectAsync_Cancel_With_InfiniteTimeout failing on Libraries Test Run release coreclr windows x86 Release #69101

Open

Add the coreclr_set_error_writer API to Mono

6f1d39a

janvorli requested review from vargaz, lambdageek and SamMonoRT as code owners November 29, 2022 09:47

Fix Mono x86 missing calling convention spec

970af28

janvorli closed this Dec 2, 2022

janvorli reopened this Dec 2, 2022

build-analysis bot mentioned this pull request Dec 2, 2022

System.IO.Pipes.Tests.NamedPipeTest_CurrentUserOnly_Windows.Connection_UnderDifferentUsers_BehavesAsExpected test failure #79052

Closed

Fix error code returned when the S.P.C. is not found

1985979

jkotas approved these changes Dec 5, 2022

View reviewed changes

AaronRobinsonMSFT approved these changes Dec 5, 2022

View reviewed changes

vitek-karas approved these changes Dec 6, 2022

View reviewed changes

build-analysis bot mentioned this pull request Dec 6, 2022

iOS & tvOS legs are failing to AOT System.Net.Http.Json #79279

Closed

janvorli merged commit ffffc4b into dotnet:main Dec 7, 2022

janvorli deleted the initialization-failures-logging-2 branch December 7, 2022 01:29

kasperk81 mentioned this pull request Dec 15, 2022

[main] Update dependencies from dotnet/runtime dotnet/sdk#29406

Merged

janvorli mentioned this pull request Jan 2, 2023

Better diagnostics for coreclr initialization failures #70211

Closed

ghost locked as resolved and limited conversation to collaborators Jan 6, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CoreCLR initialization failures logging #78790

CoreCLR initialization failures logging #78790

janvorli commented Nov 24, 2022

janvorli commented Nov 24, 2022

jkotas Nov 24, 2022

janvorli Nov 24, 2022

jkotas commented Nov 24, 2022

AaronRobinsonMSFT left a comment

janvorli commented Nov 24, 2022

jkotas commented Nov 24, 2022

jkotas Nov 24, 2022

janvorli Nov 24, 2022

elinor-fung Nov 24, 2022

janvorli Nov 24, 2022

janvorli Nov 24, 2022 •

edited

Loading

janvorli Nov 24, 2022

janvorli Nov 25, 2022

janvorli Nov 25, 2022

elinor-fung Nov 28, 2022

janvorli Nov 29, 2022

janvorli commented Dec 2, 2022

jkotas commented Dec 2, 2022

janvorli commented Dec 5, 2022

jkotas left a comment

vitek-karas Dec 6, 2022

janvorli Dec 6, 2022

vitek-karas Dec 6, 2022

janvorli commented Dec 6, 2022

MichalStrehovsky commented Dec 6, 2022

janvorli commented Dec 6, 2022

CoreCLR initialization failures logging #78790

CoreCLR initialization failures logging #78790

Conversation

janvorli commented Nov 24, 2022

janvorli commented Nov 24, 2022

Missing SPC file

Another assembly instead of SPC

Text file instead of SPC

Wrong version of SPC (x86)

Wrong version of SPC (x64 from 3.1):

OOM

Wrong setting of GC log file

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jkotas commented Nov 24, 2022

AaronRobinsonMSFT left a comment

Choose a reason for hiding this comment

janvorli commented Nov 24, 2022

jkotas commented Nov 24, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

janvorli Nov 24, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

janvorli commented Dec 2, 2022

jkotas commented Dec 2, 2022

janvorli commented Dec 5, 2022

jkotas left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

janvorli commented Dec 6, 2022

MichalStrehovsky commented Dec 6, 2022

janvorli commented Dec 6, 2022

janvorli Nov 24, 2022 •

edited

Loading