Microsoft.Extensions.Logging.Tests fail on WASM with an assertion in mono_exception_new_by_name_domain #38337

akoeplinger · 2020-06-24T15:19:54Z

Some tests in Microsoft.Extensions.Logging.Tests fail with an assertion:

Microsoft.Extensions.Logging.Test.ConsoleLoggerTest.ConsoleLoggerOptions_IncludeScopes_IsReadFromLoggingConfiguration

        Stacktrace:
        Error
            at 194359 (dotnet.js:1858:32)
            at _emscripten_asm_const_iii (dotnet.js:1863:27)
            at wasm_logger (<anonymous>:wasm-function[7792]:0x1ef32e)
            at eglib_log_adapter (<anonymous>:wasm-function[6304]:0x1a71bf)
            at monoeg_g_logstr (<anonymous>:wasm-function[7226]:0x1ca2fc)
            at monoeg_g_logv_nofree (<anonymous>:wasm-function[7224]:0x1ca223)
            at monoeg_assertion_message (<anonymous>:wasm-function[7228]:0x1ca3af)
            at mono_exception_new_by_name_domain (<anonymous>:wasm-function[2195]:0xb3b8f)
            at mono_exception_new_by_name (<anonymous>:wasm-function[2205]:0xb4790)
            at mono_exception_new_by_name_msg (<anonymous>:wasm-function[2204]:0xb450f)

        WASM-ERR: * Assertion at /Users/alexander/dev/runtime/src/mono/mono/metadata/exception.c:109, condition `is_ok (error)' not met, function:mono_exception_new_by_name_domain, (null) assembly:System.Private.CoreLib.dll type:PlatformNotSupportedException member:(null)
        WASM-ERR:
        ABORT: undefined
        Stacktrace:
        Error
            at Object.onAbort (runtime.js:160:13)
            at abort (dotnet.js:1643:22)
            at _abort (dotnet.js:6101:7)
            at wasm_logger (<anonymous>:wasm-function[7792]:0x1ef350)
            at eglib_log_adapter (<anonymous>:wasm-function[6304]:0x1a71bf)
            at monoeg_g_logstr (<anonymous>:wasm-function[7226]:0x1ca2fc)
            at monoeg_g_logv_nofree (<anonymous>:wasm-function[7224]:0x1ca223)
            at monoeg_assertion_message (<anonymous>:wasm-function[7228]:0x1ca3af)
            at mono_exception_new_by_name_domain (<anonymous>:wasm-function[2195]:0xb3b8f)
            at mono_exception_new_by_name (<anonymous>:wasm-function[2205]:0xb4790)

The problematic tests were disabled so to reproduce it you need to remove

runtime/src/libraries/Microsoft.Extensions.Logging/tests/Common/LoggerFactoryTest.cs

Line 202 in cd4c4c9

    
           [ActiveIssue("https://github.com/dotnet/runtime/issues/38337", TestPlatforms.Browser)]

The text was updated successfully, but these errors were encountered:

…ft.Extensions.Logging Filed dotnet#38337 for the tests that cause a runtime assert. The rest are normal threading ignores.

…ft.Extensions.Logging (#38338) Filed #38337 for the tests that cause a runtime assert. The rest are normal threading ignores.

lambdageek · 2020-06-30T14:40:56Z

I think this is due to

runtime/src/libraries/Microsoft.Extensions.DependencyInjection/src/ServiceLookup/DynamicServiceProviderEngine.cs

Line 25 in 54d9241

Task.Run(() => base.RealizeService(callSite));

The dynamic service provider engine is created by

runtime/src/libraries/Microsoft.Extensions.DependencyInjection/src/ServiceProvider.cs

Lines 37 to 49 in 54d9241

    
                               if (RuntimeFeature.IsSupported("IsDynamicCodeCompiled")) 
        
                               { 
        
                                   _engine = new DynamicServiceProviderEngine(serviceDescriptors, callback); 
        
                               } 
        
                               else 
        
                               { 
        
                                   // Don't try to compile Expressions/IL if they are going to get interpreted 
        
                                   _engine = new RuntimeServiceProviderEngine(serviceDescriptors, callback); 
        
                               } 
        
           #endif 
        
                               break; 
        
                           case ServiceProviderMode.Dynamic: 
        
                               _engine = new DynamicServiceProviderEngine(serviceDescriptors, callback);

It's possible that we can pass some options too the logger factory to create a different kind of service provider engine that might work on wasm. Not sure

runtime/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs

Lines 94 to 101 in 54d9241

    
           public static ILoggerFactory Create(Action<ILoggingBuilder> configure) 
        
           { 
        
               var serviceCollection = new ServiceCollection(); 
        
               serviceCollection.AddLogging(configure); 
        
               ServiceProvider serviceProvider = serviceCollection.BuildServiceProvider(); 
        
               ILoggerFactory loggerFactory = serviceProvider.GetService<ILoggerFactory>(); 
        
               return new DisposingLoggerFactory(loggerFactory, serviceProvider); 
        
           }

lambdageek · 2020-06-30T17:16:46Z

Longer stack trace:

  dbug: test[0]
        WASM-ERR: * Assertion at /Users/alklig/work/dotnet-runtime/hask-wasm/src/mono/mono/metadata/exception.c:109, condition `is_ok (error)' not met, function:mono_exception_new_by_name_domain, (null) assembly:System.Private.CoreLib.dll type:ArgumentException member:(null)
  dbug: test[0]
        WASM-ERR:
  dbug: test[0]
        ABORT: undefined
  dbug: test[0]
        Stacktrace:
  dbug: test[0]
  dbug: test[0]
        Error
  dbug: test[0]
            at Object.onAbort (runtime.js:160:13)
  dbug: test[0]
            at abort (dotnet.js:1643:22)
  dbug: test[0]
            at _abort (dotnet.js:6101:7)
  dbug: test[0]
            at wasm_logger (:wasm-function[8190]:0x207e5c)
  dbug: test[0]
            at eglib_log_adapter (:wasm-function[6345]:0x1adec1)
  dbug: test[0]
            at monoeg_g_logstr (:wasm-function[7267]:0x1d0ffe)
  dbug: test[0]
            at monoeg_g_logv_nofree (:wasm-function[7265]:0x1d0f25)
  dbug: test[0]
            at monoeg_assertion_message (:wasm-function[7269]:0x1d10b1)
  dbug: test[0]
            at mono_exception_new_by_name_domain (:wasm-function[2216]:0xb50b4)
  dbug: test[0]
            at mono_exception_new_by_name (:wasm-function[2226]:0xb5cb5)
  dbug: test[0]
            at mono_exception_new_by_name_msg (:wasm-function[2225]:0xb5a34)
  dbug: test[0]
            at mono_error_prepare_exception (:wasm-function[6278]:0x1aafed)
  dbug: test[0]
            at mono_error_convert_to_exception (:wasm-function[6285]:0x1ab5c7)
  dbug: test[0]
            at mono_error_convert_to_exception_handle (:wasm-function[2261]:0xb7789)
  dbug: test[0]
            at mono_error_set_pending_exception_slow (:wasm-function[2260]:0xb768c)
  dbug: test[0]
            at mono_error_set_pending_exception.6 (:wasm-function[3767]:0x1153a4)
  dbug: test[0]
            at mono_monitor_ensure_owned (:wasm-function[3777]:0x115d80)
  dbug: test[0]
            at mono_monitor_exit_internal (:wasm-function[3776]:0x115c6b)
  dbug: test[0]
            at mono_monitor_exit_icall (:wasm-function[3787]:0x116073)
  dbug: test[0]
            at mono_monitor_exit_icall_raw (:wasm-function[2959]:0xe45cf)
  dbug: test[0]
            at do_icall (:wasm-function[230]:0x1f496)
  dbug: test[0]
            at do_icall_wrapper (:wasm-function[190]:0x1d3f1)
  dbug: test[0]
            at interp_exec_method (:wasm-function[142]:0x75ef)
  dbug: test[0]
            at interp_run_finally (:wasm-function[151]:0x1b36c)
  dbug: test[0]
            at mono_handle_exception_internal (:wasm-function[615]:0x50b6c)
  dbug: test[0]
            at mono_handle_exception (:wasm-function[584]:0x4d20b)
  dbug: test[0]
            at interp_throw (:wasm-function[187]:0x1d25e)
  dbug: test[0]
            at interp_exec_method (:wasm-function[142]:0x7647)
  dbug: test[0]
            at interp_runtime_invoke (:wasm-function[140]:0x5876)
  dbug: test[0]
            at mono_jit_runtime_invoke (:wasm-function[909]:0x61f6c)
  dbug: test[0]
            at do_runtime_invoke (:wasm-function[4031]:0x128058)
  dbug: test[0]
            at mono_runtime_invoke_checked (:wasm-function[4029]:0x127f11)
  dbug: test[0]
            at mono_runtime_try_invoke_array (:wasm-function[4160]:0x130cfe)
  dbug: test[0]
            at mono_runtime_invoke_array_checked (:wasm-function[4163]:0x131452)
  dbug: test[0]
            at ves_icall_InternalInvoke (:wasm-function[2564]:0xca9c4)
  dbug: test[0]
            at ves_icall_InternalInvoke_raw (:wasm-function[2840]:0xde069)
  dbug: test[0]
            at do_icall (:wasm-function[230]:0x1f670)
  dbug: test[0]
            at do_icall_wrapper (:wasm-function[190]:0x1d3f1)
  dbug: test[0]
            at interp_exec_method (:wasm-function[142]:0x75ef)
  dbug: test[0]
            at interp_runtime_invoke (:wasm-function[140]:0x5876)
  dbug: test[0]
            at mono_jit_runtime_invoke (:wasm-function[909]:0x61f6c)
  dbug: test[0]
            at do_runtime_invoke (:wasm-function[4031]:0x128058)
  dbug: test[0]
            at mono_runtime_try_invoke (:wasm-function[4046]:0x128cf3)
  dbug: test[0]
            at mono_runtime_invoke (:wasm-function[4103]:0x12d0bd)
  dbug: test[0]
            at mono_wasm_invoke_method (:wasm-function[8186]:0x207c3e)
  dbug: test[0]
            at dotnet.js:1711:22
  dbug: test[0]
            at ccall (dotnet.js:751:18)
  dbug: test[0]
            at dotnet.js:763:12
  dbug: test[0]
            at Object.init (runtime.js:366:15)
  dbug: test[0]
            at runtime.js:245:9
  dbug: test[0]
            at dotnet.js:7240:9

lambdageek · 2020-06-30T19:39:25Z

Some printf debugging shows that indeed we don't own the lockword on some monitor:

small id 64, lock word owner was 0

The initial part of the managed stack looks like this by the time we try to do the monitor exit:

L: Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver:VisitCache (Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceCallSite,Microsoft.Extensions.DependencyInjection.ServiceLookup.RuntimeResolverContext,Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope,Microsoft.Extensions.DependencyInjection.ServiceLookup.RuntimeResolverLock)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver:VisitRootCache (Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceCallSite,Microsoft.Extensions.DependencyInjection.ServiceLookup.RuntimeResolverContext)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2<Microsoft.Extensions.DependencyInjection.ServiceLookup.RuntimeResolverContext, object>:VisitCallSite (Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceCallSite,Microsoft.Extensions.DependencyInjection.ServiceLookup.RuntimeResolverContext)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver:Resolve (Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceCallSite,Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceLookup.RuntimeServiceProviderEngine/<>c__DisplayClass1_0:<RealizeService>b__1 (Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceLookup.RuntimeServiceProviderEngine/<>c__DisplayClass1_0:<RealizeService>b__0 (Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine:GetService (System.Type,Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine:GetService (System.Type)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceProvider:GetService (System.Type)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions:GetRequiredService (System.IServiceProvider,System.Type)
  dbug: test[0]
        L: Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions:GetRequiredService<Microsoft.Extensions.Logging.ILoggerProvider> (System.IServiceProvider)
  dbug: test[0]
        L: Microsoft.Extensions.Logging.Test.ConsoleLoggerTest:ConsoleLoggerOptions_DisableColors_IsReadFromLoggingConfiguration ()
  dbug: test[0]
        L: System.Reflection.RuntimeMethodInfo:Invoke (object,System.Reflection.BindingFlags,System.Reflection.Binder,object[],System.Globalization.CultureInfo)

lambdageek · 2020-06-30T21:03:43Z

Current theory is that we call Monitor.Exit too many times, somehow. Because all the Enter calls definitely own the monitor object.

vargaz · 2020-07-14T16:14:22Z

Testcase:

using System;
using System.Reflection;

public class Test
{
    public static void foo4 () {
        throw new Exception ();
    }

    public static void Main (String[] args) {
        try {
            foo3 ();
        } catch (Exception) {
        }
        Console.WriteLine (count);
    }

    static int count;

    public static void foo3 () {
        try {
            typeof (Test).GetMethod ("foo4").Invoke (null, BindingFlags.DoNotWrapExceptions, null, null, null);
        } finally {
            count ++;
        }
    }
}

This will print '2' under wasm, which means the finally clause is executed twice.

vargaz · 2020-07-14T16:17:43Z

It doesn't fail under the desktop interpreter, only on wasm.

vargaz · 2020-07-14T18:37:12Z

This happens because of differences in EH implementation on wasm. wasm hits this codepath:

#if defined (MONO_CROSS_COMPILE) || defined (HOST_WASM)
#define INTERP_PUSH_LMF_WITH_CTX_BODY(ext, exit_label) \
	(ext).kind = MONO_LMFEXT_INTERP_EXIT;

So after this call in interp_runtime_invoke ():

	interp_exec_method (&frame, context, NULL);

This codepath is hit only on wasm:

	if (context->has_resume_state) {
         }

That if block doesn't seem to do the right thing, which causes the different behavior with the testcase on wasm.

The previous code would convert exceptions into errors which would be rethrown later, clearing the resume state. Hopefully fixes dotnet/runtime#38337.

The previous code would convert exceptions into errors which would be rethrown later, clearing the resume state. Hopefully fixes dotnet#38337.

…ft.Extensions.Logging (#38338) Filed dotnet/runtime#38337 for the tests that cause a runtime assert. The rest are normal threading ignores.

…9316) The previous code would convert exceptions into errors which would be rethrown later, clearing the resume state. Hopefully fixes #38337. Co-authored-by: vargaz <vargaz@users.noreply.github.com>

…0117) The previous code would convert exceptions into errors which would be rethrown later, clearing the resume state. Hopefully fixes dotnet/runtime#38337.

vargaz · 2020-07-15T06:23:48Z

This will probably fail with a PNSE now.

…ct instead, since the test still fails.

…tead, since the test still fails. (#39348)

vargaz · 2020-07-15T12:33:51Z

Should be fixed.

akoeplinger added the area-VM-meta-mono label Jun 24, 2020

akoeplinger added this to the 5.0.0 milestone Jun 24, 2020

Dotnet-GitSync-Bot added the untriaged New issue has not been triaged by the area owner label Jun 24, 2020

akoeplinger mentioned this issue Jun 24, 2020

[wasm] Disable threading and other tests that cause issues in Microsoft.Extensions.Logging #38338

Merged

akoeplinger added a commit that referenced this issue Jun 24, 2020

[wasm] Disable threading and other tests that cause issues in Microso…

02489cd

…ft.Extensions.Logging (#38338) Filed #38337 for the tests that cause a runtime assert. The rest are normal threading ignores.

marek-safar added arch-wasm WebAssembly architecture and removed untriaged New issue has not been triaged by the area owner labels Jun 30, 2020

marek-safar assigned lambdageek Jun 30, 2020

lambdageek assigned vargaz Jul 8, 2020

vargaz mentioned this issue Jul 14, 2020

[wasm] Fix the propagation of exceptions through runtime invokes. mono/mono#20117

Merged

monojenkins mentioned this issue Jul 14, 2020

[wasm] Fix the propagation of exceptions through runtime invokes. #39316

Merged

vargaz closed this as completed in #39316 Jul 15, 2020

vargaz reopened this Jul 15, 2020

akoeplinger mentioned this issue Jul 15, 2020

[wasm] Remove ActiveIssue for issue #38337. Add a ConditionalFact instead, since the test still fails. #39348

Merged

vargaz added a commit to vargaz/runtime that referenced this issue Jul 15, 2020

[wasm] Remove ActiveIssue for issue dotnet#38337. Add a ConditionalFa…

6ccb951

…ct instead, since the test still fails.

vargaz added a commit that referenced this issue Jul 15, 2020

[wasm] Remove ActiveIssue for issue #38337. Add a ConditionalFact ins…

83a15e3

…tead, since the test still fails. (#39348)

vargaz closed this as completed Jul 15, 2020

MaximLipnin mentioned this issue Aug 3, 2020

[wasm] Re-enable some Microsoft.Extensions.Logging.Tests tests on browser-wasm. #40255

Merged

ghost locked as resolved and limited conversation to collaborators Dec 8, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Microsoft.Extensions.Logging.Tests fail on WASM with an assertion in mono_exception_new_by_name_domain #38337

Microsoft.Extensions.Logging.Tests fail on WASM with an assertion in mono_exception_new_by_name_domain #38337

akoeplinger commented Jun 24, 2020 •

edited

Loading

lambdageek commented Jun 30, 2020

lambdageek commented Jun 30, 2020 •

edited

Loading

lambdageek commented Jun 30, 2020

lambdageek commented Jun 30, 2020

vargaz commented Jul 14, 2020

vargaz commented Jul 14, 2020

vargaz commented Jul 14, 2020 •

edited

Loading

vargaz commented Jul 15, 2020

vargaz commented Jul 15, 2020

Microsoft.Extensions.Logging.Tests fail on WASM with an assertion in mono_exception_new_by_name_domain #38337

Microsoft.Extensions.Logging.Tests fail on WASM with an assertion in mono_exception_new_by_name_domain #38337

Comments

akoeplinger commented Jun 24, 2020 • edited Loading

lambdageek commented Jun 30, 2020

lambdageek commented Jun 30, 2020 • edited Loading

lambdageek commented Jun 30, 2020

lambdageek commented Jun 30, 2020

vargaz commented Jul 14, 2020

vargaz commented Jul 14, 2020

vargaz commented Jul 14, 2020 • edited Loading

vargaz commented Jul 15, 2020

vargaz commented Jul 15, 2020

akoeplinger commented Jun 24, 2020 •

edited

Loading

lambdageek commented Jun 30, 2020 •

edited

Loading

vargaz commented Jul 14, 2020 •

edited

Loading