Segmentation fault with NLog on linux-arm, related to "Recursive resource lookup bug"?

[BrendanGrant]

I had a dotnet core 2.0 app running fine on a Raspberry Pi 2 (running Raspbian) fine for many months, until the sd card gave up, so setup a new card with a fresh install of Raspbian & deployed an upgraded version (still targeting 2.0) with upgrades to the latest NuGet projects suddenly caused it to fail with the following error:

Assert Failure
Expression: [Recursive resource lookup bug]
Description: Infinite recursion during resource lookup within System.Private.CoreLib. This may be a bug in System.Private.CoreLib, or potentially in certain extensibility points such as assembly resolve events or CultureInfo names. Resource name: ArgumentNull_Generic
Stack Trace:
at System.SR.InternalGetResourceString(String key)
at System.SR.GetResourceString(String resourceKey, String defaultString)
at System.ArgumentNullException..ctor(String paramName)
at System.Runtime.Loader.AssemblyLoadContext.GetLoadContext(Assembly assembly)
at System.Reflection.Assembly.LoadFromResolveHandler(Object sender, ResolveEventArgs args)
at System.AppDomain.OnAssemblyResolveEvent(RuntimeAssembly assembly, String assemblyFullName)
at System.Reflection.RuntimeAssembly._nLoad(AssemblyName fileName, String codeBase, Evidence assemblySecurity, RuntimeAssembly locationHint, StackCrawlMark& stackMark, IntPtr pPrivHostBinder, Boolean throwOnFileNotFound, Boolean forIntrospection, Boolean suppressSecurityChecks, IntPtr ptrLoadContextBinder)
at System.Reflection.RuntimeAssembly.InternalGetSatelliteAssembly(String name, CultureInfo culture, Version version, Boolean throwOnFileNotFound, StackCrawlMark& stackMark)
at System.Resources.ManifestBasedResourceGroveler.GetSatelliteAssembly(CultureInfo lookForCulture, StackCrawlMark& stackMark)
at System.Resources.ManifestBasedResourceGroveler.GrovelForResourceSet(CultureInfo culture, Dictionary2 localResourceSets, Boolean tryParents, Boolean createIfNotExists, StackCrawlMark& stackMark) at System.Resources.ResourceManager.InternalGetResourceSet(CultureInfo requestedCulture, Boolean createIfNotExists, Boolean tryParents, StackCrawlMark& stackMark) at System.Resources.ResourceManager.InternalGetResourceSet(CultureInfo culture, Boolean createIfNotExists, Boolean tryParents) at System.Resources.ResourceManager.GetString(String name, CultureInfo culture) at System.SR.InternalGetResourceString(String key) at System.SR.GetResourceString(String resourceKey, String defaultString) at System.ArgumentNullException..ctor(String paramName) at System.Runtime.Loader.AssemblyLoadContext.GetLoadContext(Assembly assembly) at System.Reflection.Assembly.LoadFromResolveHandler(Object sender, ResolveEventArgs args) at System.AppDomain.OnAssemblyResolveEvent(RuntimeAssembly assembly, String assemblyFullName) at System.Reflection.RuntimeAssembly._nLoad(AssemblyName fileName, String codeBase, Evidence assemblySecurity, RuntimeAssembly locationHint, StackCrawlMark& stackMark, IntPtr pPrivHostBinder, Boolean throwOnFileNotFound, Boolean forIntrospection, Boolean suppressSecurityChecks, IntPtr ptrLoadContextBinder) at System.Reflection.RuntimeAssembly.InternalGetSatelliteAssembly(String name, CultureInfo culture, Version version, Boolean throwOnFileNotFound, StackCrawlMark& stackMark) at System.Resources.ManifestBasedResourceGroveler.GetSatelliteAssembly(CultureInfo lookForCulture, StackCrawlMark& stackMark) at System.Resources.ManifestBasedResourceGroveler.GrovelForResourceSet(CultureInfo culture, Dictionary2 localResourceSets, Boolean tryParents, Boolean createIfNotExists, StackCrawlMark& stackMark)
at System.Resources.ResourceManager.InternalGetResourceSet(CultureInfo requestedCulture, Boolean createIfNotExists, Boolean tryParents, StackCrawlMark& stackMark)
at System.Resources.ResourceManager.InternalGetResourceSet(CultureInfo culture, Boolean createIfNotExists, Boolean tryParents)
at System.Resources.ResourceManager.GetString(String name, CultureInfo culture)
at System.SR.InternalGetResourceString(String key)
at System.SR.GetResourceString(String resourceKey, String defaultString)
at System.SR.get_Arg_ArgumentException()
at PowerPi.Program.Main(String[] args) in C:\Users\grant\source\repos\PowerPi\PowerPi\Program.cs:line 22
Segmentation fault

This sounded rather similar to https://github.com/dotnet/corefx/issues/23608 (just one of many though), and using it's advice I created a new ArgumetnException() in my main to trigger it faster (as seen above in stacktrace).

Whittling things down into a standalone repro... I build a new stand alone project, added a NuGet reference to NLog.Extensions.Logging, added a NLog.config to the project which always copies to output directory, with the following contents:

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <targets>
    <target name="console" xsi:type="Console" />
  </targets>

  <rules>
    <logger name="*" minlevel="Info" writeTo="console" />
  </rules>
</nlog>

Then updated the Program.cs file to be the following:

using System;

namespace foo1
{
    class Program
    {
        static Logger logger = LogManager.GetLogger("GoingToCrash");
        static void Main(string[] args)
        {
            logger.Info("Hello World!");
            new ArgumentException();
            logger.Info("Boom?");
        }
    }
}

When I build/publish this demo app with:

dotnet publish --runtime linux-arm --configuration Release

To my Pi2... it fails with the above stacktrace. If I follow the advice of https://github.com/dotnet/corefx/issues/26292 and add the bolded text to the rather simple csproj:

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>netcoreapp2.0</TargetFramework>
  </PropertyGroup>
***  <PropertyGroup>
    <RuntimeFrameworkVersion>2.0.5</RuntimeFrameworkVersion>
  </PropertyGroup>***

  <ItemGroup>
    <PackageReference Include="NLog.Extensions.Logging" Version="1.0.0-rtm-rc7" />
  </ItemGroup>

  <ItemGroup>
    <None Update="NLog.config">
      <CopyToOutputDirectory>Always</CopyToOutputDirectory>
    </None>
  </ItemGroup>

</Project>

There is a slight improvement... it still suffers from a segmentation fault, only you don't see the stack trace.

Attached is the rather simplistic repro, which of course works fine on my Windows 10 machine, but fails on Raspbian GNU/Linux 9 (stretch).

Build environment details:

.NET Command Line Tools (2.1.100)

Product Information:
 Version:            2.1.100
 Commit SHA-1 hash:  b9e74c6520

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.16299
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.1.100\

Microsoft .NET Core Shared Framework Host

  Version  : 2.0.5
  Build    : 17373eb129b3b05aa18ece963f8795d65ef8ea54

coreclr-segfault-with-nlog-on-linux-arm.zip

[danmoseley]

This is probably the issue:

The default runtime for standalone apps is 2.0.0 if available and it's running against that, which doesn't contain the fix. For standalone apps it's necessary to set this attribute in the .csproj to reference a specific version:

<PropertyGroup>
  <RuntimeFrameworkVersion>2.0.5</RuntimeFrameworkVersion>
</PropertyGroup>

Or <RuntimeFrameworkVersion>2.0.*</RuntimeFrameworkVersion> to target the latest published 2.0.x runtime.

[danmoseley]

In other words standalone apps don't "float forward" even for patch versions. They really are isolated in that way.

[danmoseley]

Oops - I missed that you already got that far...

[danmoseley]

So with the 2.0.5 specified, maybe the segfault is something unrelated. CAn you get a stack trace under gdb or lldb?

[BrendanGrant]

Here you go:

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
[New Thread 0x764b5450 (LWP 32346)]
[New Thread 0x75aff450 (LWP 32347)]
[New Thread 0x750ff450 (LWP 32348)]
[New Thread 0x728fe450 (LWP 32349)]
2018-03-12 00:22:52.3855|INFO|GoingToCrash|Hello World!
2018-03-12 00:22:53.5009|INFO|GoingToCrash|Boom?

Thread 5 "foo1" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x728fe450 (LWP 32349)]
0x766d4b9e in EventPipeConfiguration::RegisterProvider(EventPipeProvider&) ()
   from /home/pi/test/libcoreclr.so

bt gives us:

#0  0x766d4b9e in EventPipeConfiguration::RegisterProvider(EventPipeProvider&)
    () from /home/pi/test/libcoreclr.so
dotnet/corefx#1  0x766d5b04 in EventPipeProvider::EventPipeProvider(_GUID const&, void (*)(_GUID const*, unsigned int, unsigned char, unsigned long long, unsigned long long, void*, void*), void*) () from /home/pi/test/libcoreclr.so
dotnet/corefx#2  0x766d4534 in EventPipeInternal::CreateProvider(_GUID, void (*)(_GUID const*, unsigned int, unsigned char, unsigned long long, unsigned long long, void*, void*)) () from /home/pi/test/libcoreclr.so
dotnet/corefx#3  0x6eb5165c in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

I'll have to look into how to install/use lldb for more details.

[danmoseley]

Ah that is https://github.com/dotnet/coreclr/issues/14997 which is in the servicing branch but has not shipped yet as there was a delay. I hope it goes out next month.

@brianrob is there a workaround for this? It sounds like @BrendanGrant is getting it consistently on Raspberry PI

[danmoseley]

It should be in 2.0.7 BTW. 2.0.6 is expected to go out shortly.

[BrendanGrant]

Thanks @danmosemsft, it sounds related and would fix my dummy repro case... but it seems my larger app remains borked on the Pi, even when setting the RuntimeFrameworkVersion to 2.0.5.

Unlike the repro which just seg faults semi quietly, the added new ArgumentException() near the top of Main() still causes the giant [Recursive resource lookup bug] related stack trace... followed by a terminal seg fault. If I don't have the new ArgumentException(), the program will fail about 20 seconds later when another bit of code tries to do it's thing.

The entire thing in gdb looks like:

GNU gdb (Raspbian 7.12-6) 7.12.0.20161007-git
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from PowerPi...(no debugging symbols found)...done.
(gdb) r
Starting program: /home/pi/pp/PowerPi
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
[New Thread 0x764b5450 (LWP 10629)]
[New Thread 0x75aff450 (LWP 10630)]
[New Thread 0x750ff450 (LWP 10631)]
[New Thread 0x748ff450 (LWP 10632)]
2018-03-12 02:11:33.6855|INFO|MainPowerPiProgram|PowerPi startup...
Assert Failure
Expression: [Recursive resource lookup bug]
Description: Infinite recursion during resource lookup within System.Private.CoreLib.  This may be a bug in System.Private.CoreLib, or potentially in certain extensibility points such as assembly resolve events or CultureInfo names.  Resource name: ArgumentNull_Generic
Stack Trace:
   at System.SR.InternalGetResourceString(String key)
   at System.SR.GetResourceString(String resourceKey, String defaultString)
   at System.ArgumentNullException..ctor(String paramName)
   at System.Runtime.Loader.AssemblyLoadContext.GetLoadContext(Assembly assembly)
   at System.Reflection.Assembly.LoadFromResolveHandler(Object sender, ResolveEventArgs args)
   at System.AppDomain.OnAssemblyResolveEvent(RuntimeAssembly assembly, String assemblyFullName)
   at System.Reflection.RuntimeAssembly._nLoad(AssemblyName fileName, String codeBase, Evidence assemblySecurity, RuntimeAssembly locationHint, StackCrawlMark& stackMark, IntPtr pPrivHostBinder, Boolean throwOnFileNotFound, Boolean forIntrospection, Boolean suppressSecurityChecks, IntPtr ptrLoadContextBinder)
   at System.Reflection.RuntimeAssembly.InternalGetSatelliteAssembly(String name, CultureInfo culture, Version version, Boolean throwOnFileNotFound, StackCrawlMark& stackMark)
   at System.Resources.ManifestBasedResourceGroveler.GetSatelliteAssembly(CultureInfo lookForCulture, StackCrawlMark& stackMark)
   at System.Resources.ManifestBasedResourceGroveler.GrovelForResourceSet(CultureInfo culture, Dictionary`2 localResourceSets, Boolean tryParents, Boolean createIfNotExists, StackCrawlMark& stackMark)
   at System.Resources.ResourceManager.InternalGetResourceSet(CultureInfo requestedCulture, Boolean createIfNotExists, Boolean tryParents, StackCrawlMark& stackMark)
   at System.Resources.ResourceManager.InternalGetResourceSet(CultureInfo culture, Boolean createIfNotExists, Boolean tryParents)
   at System.Resources.ResourceManager.GetString(String name, CultureInfo culture)
   at System.SR.InternalGetResourceString(String key)
   at System.SR.GetResourceString(String resourceKey, String defaultString)
   at System.ArgumentNullException..ctor(String paramName)
   at System.Runtime.Loader.AssemblyLoadContext.GetLoadContext(Assembly assembly)
   at System.Reflection.Assembly.LoadFromResolveHandler(Object sender, ResolveEventArgs args)
   at System.AppDomain.OnAssemblyResolveEvent(RuntimeAssembly assembly, String assemblyFullName)
   at System.Reflection.RuntimeAssembly._nLoad(AssemblyName fileName, String codeBase, Evidence assemblySecurity, RuntimeAssembly locationHint, StackCrawlMark& stackMark, IntPtr pPrivHostBinder, Boolean throwOnFileNotFound, Boolean forIntrospection, Boolean suppressSecurityChecks, IntPtr ptrLoadContextBinder)
   at System.Reflection.RuntimeAssembly.InternalGetSatelliteAssembly(String name, CultureInfo culture, Version version, Boolean throwOnFileNotFound, StackCrawlMark& stackMark)
   at System.Resources.ManifestBasedResourceGroveler.GetSatelliteAssembly(CultureInfo lookForCulture, StackCrawlMark& stackMark)
   at System.Resources.ManifestBasedResourceGroveler.GrovelForResourceSet(CultureInfo culture, Dictionary`2 localResourceSets, Boolean tryParents, Boolean createIfNotExists, StackCrawlMark& stackMark)
   at System.Resources.ResourceManager.InternalGetResourceSet(CultureInfo requestedCulture, Boolean createIfNotExists, Boolean tryParents, StackCrawlMark& stackMark)
   at System.Resources.ResourceManager.InternalGetResourceSet(CultureInfo culture, Boolean createIfNotExists, Boolean tryParents)
   at System.Resources.ResourceManager.GetString(String name, CultureInfo culture)
   at System.SR.InternalGetResourceString(String key)
   at System.SR.GetResourceString(String resourceKey, String defaultString)
   at System.SR.get_Arg_ArgumentException()
   at PowerPi.Program.Main(String[] args) in C:\Users\grant\source\repos\PowerPi\PowerPi\Program.cs:line 22

Thread 3 "PowerPi" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x75aff450 (LWP 10630)]
0x766d4a0e in EventPipeConfiguration::RegisterProvider(EventPipeProvider&) ()
   from /home/pi/pp/libcoreclr.so
(gdb) bt
#0  0x766d4a0e in EventPipeConfiguration::RegisterProvider(EventPipeProvider&)
    () from /home/pi/pp/libcoreclr.so
dotnet/corefx#1  0x766d5974 in EventPipeProvider::EventPipeProvider(_GUID const&, void (*)(_GUID const*, unsigned int, unsigned char, unsigned long long, unsigned long long, void*, void*), void*) () from /home/pi/pp/libcoreclr.so
dotnet/corefx#2  0x766d43a4 in EventPipeInternal::CreateProvider(_GUID, void (*)(_GUID const*, unsigned int, unsigned char, unsigned long long, unsigned long long, void*, void*)) () from /home/pi/pp/libcoreclr.so
dotnet/corefx#3  0x6ea9ab24 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb)

The startup code is remaribily simple:

    {
        static Logger logger = LogManager.GetLogger("MainPowerPiProgram");
        static void Main(string[] args)
        {
            Environment.SetEnvironmentVariable("DOTNET_CLI_TELEMETRY_OPTOUT", "1");

            logger.Info("PowerPi startup...");
            new ArgumentException();
            logger.Info("Remember, all times are UTC.");

The first logger message will be dumped to the console, but the second one never does... unlike the mentioned repro.

I agree that https://github.com/dotnet/coreclr/issues/14997 is a candidate for blame wrt the seg fault.. there is still the oddity of the stack trace causing the terminal condition in the first place.

[danmoseley]

@kouvel can you help make sense of this? Wasnt it you who likes at the original Issue?

[danmoseley]

Oh what culture is in play here? What is cultureinfo.CurrentCulture? I seem to remember the workaround only helped in en-US

[BrendanGrant]

en-GB is the CurrentCulture, as it's largely a stock Rasbian install.

I used raspi-config to change the default culture... but that didn't seem to stick, I've not tried a reboot yet.

I manually set CultureInfo.CurrentCulture = new CultureInfo("en-US") before the new ArgumentException() and it still fell over.

On a lark, I also set CultureInfo.CurrentUICulture = new CultureInfo("en-US") immediately afterwards.

That was not the workaround I was expecting.

Worse, this sounds like https://github.com/dotnet/corefx/issues/23608 which is reported to be fixed in 2.0.3... regression?

[danmoseley]

From the original Issue :

The exact trigger for this bug is: there is a AssemblyResolve handler that has a bug: it either returns an assembly that does not match or it throws. It turns out that Assembly.LoadFrom always registers an AssemblyResolve handler with this bug. So another workaround is to remove such an AssemblyResolve handler, and avoid Assembly.LoadFrom. Of course, very often the app does not control whever code is doing this

I'm guessing your static field initializer that does Get logger is doing Load from. Can you make it happen after the Argument exception? Keep setting the en-US before that also.

[danmoseley]

@tarekgh may also be able to help

[BrendanGrant]

Currently the init of the program is (with workarounds and extra logging):

        static Logger logger = LogManager.GetLogger("MainPowerPiProgram");
        static void Main(string[] args)
        {
            Environment.SetEnvironmentVariable("DOTNET_CLI_TELEMETRY_OPTOUT", "1");

            CultureInfo.CurrentCulture = new CultureInfo("en-US");
            CultureInfo.CurrentUICulture = new CultureInfo("en-US");

            Console.WriteLine(CultureInfo.CurrentCulture?.ToString());
            Console.WriteLine(CultureInfo.CurrentUICulture?.ToString());

            logger.Info("PowerPi startup...");
            new ArgumentException();
            logger.Info("Remember, all times are UTC.");

Commenting things out I get the following:

        static Logger logger = null; //LogManager.GetLogger("MainPowerPiProgram");
        static void Main(string[] args)
        {
            Environment.SetEnvironmentVariable("DOTNET_CLI_TELEMETRY_OPTOUT", "1");

            //CultureInfo.CurrentCulture = new CultureInfo("en-US");
            //CultureInfo.CurrentUICulture = new CultureInfo("en-US");

            //Console.WriteLine(CultureInfo.CurrentCulture?.ToString());
            //Console.WriteLine(CultureInfo.CurrentUICulture?.ToString());

            //logger.Info("PowerPi startup...");
            new ArgumentException();
            //logger.Info("Remember, all times are UTC.");

            logger = LogManager.GetLogger("MainPowerPiProgram");

            Console.WriteLine(CultureInfo.CurrentCulture?.ToString());
            Console.WriteLine(CultureInfo.CurrentUICulture?.ToString());

And sure enough it works... while still reporting en-GB as both culture settings. Also works if I set

On the plus side... we've two different work-around... both plenty odd.

1. Explicitly setting CurrentCulture & CurrentUICulture, or
2. Delaying calling of LogManager.GetLogger until after the new ArgumentException() has kicked off.

[danmoseley]

Hopefully this is enough until 2.0.7. Or you can use 2.1 preview 1 which should have neither issue...