Diagnostics: Unable to run dotnet dump in 3.1 docker container - “Process 1 not running compatible .NET Core runtime”

[matthewrk]

Recently run into a memory leak after updating from 2.0 to 3.1 and trying to diagnose by first taking a core dump but having several problems achieving that. My app runs in a docker container based off of mcr.microsoft.com/dotnet/core/sdk:3.1 for build and mcr.microsoft.com/dotnet/core/aspnet:3.1-bionic for runtime.

For debug purposes I'm using mcr.microsoft.com/dotnet/core/sdk:3.1-bionic then installing the required tools:

dotnet tool install -g dotnet-dump
dotnet tool install -g dotnet-counters
dotnet tool install -g dotnet-trace

When I attempt to run dotnet-trace to grab the pid it returns a different pid each time:

root@499333cca890:/app# dotnet trace ps
      1290 dotnet     /usr/share/dotnet/dotnet

root@499333cca890:/app# dotnet trace ps
      1311 dotnet     /usr/share/dotnet/dotnet

root@499333cca890:/app# dotnet trace ps
      1332 dotnet     /usr/share/dotnet/dotnet

I'm assuming that's the pid of the trace itself and its not actually picking up my app. The pid reported by ps aux is 1:

root@499333cca890:/app# ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.4  7.7 21890008 158932 ?     Ssl  05:52   1:14 dotnet MyApp.dll

If I attempt to take a core dump via _dotnet core dump collect -p 1_ I get the following:

Process 1 not running compatible .NET Core runtime.

Here's the output from dotnet --info:

.NET Core SDK (reflecting any global.json):
 Version:   3.1.302
 Commit:    41faccf259

Runtime Environment:
 OS Name:     ubuntu
 OS Version:  18.04
 OS Platform: Linux
 RID:         ubuntu.18.04-x64
 Base Path:   /usr/share/dotnet/sdk/3.1.302/

Host (useful for support):
  Version: 3.1.6
  Commit:  3acd9b0cd1

.NET Core SDKs installed:
  3.1.302 [/usr/share/dotnet/sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.App 3.1.6 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 3.1.6 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

And here's the target framework from my csproj:

<TargetFramework>netcoreapp3.1</TargetFramework>

As for docker, I'm setting privileged and SYS_PTRACE but still no luck:

docker run -d --privileged --cap-add SYS_PTRACE [...]

As far as I can tell the versions are all ok? It's a 3.1 app running in the 3.1 sdk with the tools installed through that.

[josalem]

While your target app is running, do you see a socket in /tmp with a name like dotnet-diagnostic-1-<epoch>? If that file isn't there, the tools won't be able to communicate with the target process. Based on the hash in the prompts you pasted above, I'm assuming that you are running everything in the same container instance with the same user (the default root user). As you said, the versions _should_ all work out.

[matthewrk]

@josalem I don't have that socket in /tmp, I have:

prwx------ 1 root root    0 Aug 11 17:01 clr-debug-pipe-1-16386-in
prwx------ 1 root root    0 Aug 11 17:01 clr-debug-pipe-1-16386-out
drwxr-xr-x 2 root root 4.0K Aug 11 17:02 system-commandline-sentinel-files

And a few other randoms.

It is all running in the same container instance with the same user. The container runs the app with CMD ["dotnet", "MyApp.dll"] and then I'm using docker exec to get a shell. I can confirm the app is actually running and responding to web requests too.

Are there any absolutely required settings/flags/config options that are needed to make this work? perhaps I'm missing something like that.

[josalem]

Thanks! Hmmm, that is certainly interesting. You have the debugger pipes, but not the Diagnostic IPC socket. You shouldn't need to set any flags for the socket to be created. Let me see if I repro this locally. If you change your container entry point to something else and launch your application while docker exec'd into the container does the socket appear?

[josalem]

I just tried running this locally with a hello world app and I didn't see it repro.

I just did:

FROM mcr.microsoft.com/dotnet/core/sdk:3.1 as BUILD

COPY . /appsrc

RUN cd /appsrc && dotnet build -c Release && dotnet publish -c Release -o ./publishedapp

FROM mcr.microsoft.com/dotnet/core/sdk:3.1-bionic as DEBUG

COPY --from=BUILD /appsrc/publishedapp /app

CMD [ "dotnet", "/app/BasicConsoleApp.dll" ]

and then ran it with

docker run -d repro:1419

and then

docker exec -it <hash> bash

and I saw the socket in /tmp.

Is there anything that you did differently from my basic repro?

[matthewrk]

@josalem thanks for doing that! I didn't see any differences that stood out in your dockerfile so I created a new web project which worked out of the box, so then compared bit by bit.

I've got it down to the Main method in Program.cs:

CreateHostBuilder(args).Build().Run() = diagnostics socket present
CreateHostBuilder(args).Start() = diagnostics socket missing

Not quite sure what the difference is there, they both seem to go down the same path with Start calling Build then StartAsync and Run calling RunAsync which in turn calls StartAsync, so I think they both end up at the same method but Start is terminating the async by calling .GetAwaiter().GetResult(); on the returned task.

It seems that all new samples use Build().Run() so I'm not sure where I picked up Start() from, but its an older dotnet core app so its been through some changes and upgrades to how things are done.

Not sure if you'd have any insight into the above?

[josalem]

That is very bizarre... Let me see if I can repro that behavior. The app itself is running on the 3.1.6 host you have listed above in both scenarios, so I'm not sure why that API difference would affect behavior of the runtime itself.

CC @dotnet/dotnet-diag

[josalem]

Okay, so I can repro this locally on my Mac (and I'm assuming any other platform) by using Start() instead of Built().Run(). I built a new webapi using the netcoreapp3.1 template and modified it to use Start() like you mentioned:

        public static void Main(string[] args)
        {
            // ...

            if (useStart)
                CreateHostBuilder(args).Start();
            else
                CreateHostBuilder(args).Build().Run();
        }

Using Start() actually shouldn't be able to work and the process tries to shut down:

info: Microsoft.Hosting.Lifetime[0]
      Now listening on: https://localhost:5001
info: Microsoft.Hosting.Lifetime[0]
      Now listening on: http://localhost:5000
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: /Users/josalem/git/scratch/BasicWebApi
info: Microsoft.Hosting.Lifetime[0]
      Application is shutting down...
info: Microsoft.Hosting.Lifetime[0]
      Waiting for the host to be disposed. Ensure all 'IHost' instances are wrapped in 'using' blocks.

There are some missing using blocks according to the logs if you just swap the APIs out. Despite the process attempting to shut down, the application is still alive and responding to web requests, but the diagnostics socket is not present. I can't seem to find a reference to the Start method in the docs going back to 2.1 even, so I'm assuming you should be using .Build().Run() regardless.

@davidfowl can you chime in on what's going on with ASP.NET here or point me to someone who could? I'm guessing this has something to do with hosting for ASP.NET.

[davidfowl]

Start isn't blocking. It'll unwind the process and hang deep in a background thread somewhere (if you don't call dispose).

[josalem]

Looks like we end up in a state where the IHost spun a background thread that is blocking shutdown, but the main thread has already started shutting down. The main thread is in EEShutdownHelper which is one of the last things that gets called on process teardown. It is trying to clear the finalizer queue and raise shutdown events, but for some reason the host thread is blocking shutdown. At this point, the diagnostics server has already been shutdown which is why you can't see the socket anymore, @matthewrk.

 # Child-SP          RetAddr               : Args to Child                                                           : Call Site
00 000000f8`2377e818 00007fff`355c8910     : <omitted> : ntdll!
01 000000f8`2377e820 00007ffe`b76dc838     : <omitted> : KERNELBASE!
02 (Inline Function) --------`--------     : --------`-------- --------`-------- --------`-------- --------`-------- : coreclr!Thread::DoAppropriateAptStateWait+0x41 (Inline Function @ 00007ffe`b76dc838) [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 3309] 
03 000000f8`2377eb10 00007ffe`b76dc601     : 00007ffe`00000001 00000000`00000001 00000237`23c14e80 00000000`00000000 : coreclr!Thread::DoAppropriateWaitWorker+0x1f8 [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 3441] 
04 000000f8`2377ec00 00007ffe`b76dba95     : 00007ffe`b7ab18f0 ffffffff`00000001 00000237`00000001 00000000`00000060 : coreclr!Thread::DoAppropriateWait+0x89 [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 3158] 
05 (Inline Function) --------`--------     : --------`-------- --------`-------- --------`-------- --------`-------- : coreclr!CLREventBase::WaitEx+0x53 (Inline Function @ 00007ffe`b76dba95) [F:\workspace\_work\1\s\src\coreclr\src\vm\synch.cpp @ 464] 
06 000000f8`2377ec80 00007ffe`b77c4a29     : 00000000`00000000 00000237`23c55580 ffffffff`ffffffff 00007ffe`00000001 : coreclr!CLREventBase::Wait+0x59 [F:\workspace\_work\1\s\src\coreclr\src\vm\synch.cpp @ 418] 
07 000000f8`2377ecd0 00007ffe`b76bbff6     : 000000f8`2377ecc8 00007ffe`b7ab18f0 00000000`00000000 00000000`00000001 : coreclr!FinalizerThread::RaiseShutdownEvents+0x59 [F:\workspace\_work\1\s\src\coreclr\src\vm\finalizerthread.h @ 67] 
08 000000f8`2377ed00 00007ffe`b76bbd5a     : 000000f8`0002a220 00000000`00000000 00000237`2224fbd0 00007ffe`b7752e60 : coreclr!EEShutDownHelper+0x27e [F:\workspace\_work\1\s\src\coreclr\src\vm\ceemain.cpp @ 1280] 
09 000000f8`2377ef10 00007ffe`b77c3510     : 00000000`00000000 00000237`2224fb60 000000f8`2377f0d0 00007ffe`cf9601f7 : coreclr!EEShutDown+0x6a [F:\workspace\_work\1\s\src\coreclr\src\vm\ceemain.cpp @ 1689] 
0a 000000f8`2377ef50 00007ffe`b77c35a9     : 00000237`221cd660 00000000`00000000 00000237`00000000 00007fff`351e8996 : coreclr!CorHost2::UnloadAppDomain2+0x40 [F:\workspace\_work\1\s\src\coreclr\src\vm\corhost.cpp @ 927] 
0b 000000f8`2377ef80 00007ffe`cf948c03     : 00000237`2224dec0 000000f8`2377f0d0 00000000`00000000 00000000`00000001 : coreclr!coreclr_shutdown_2+0x59 [F:\workspace\_work\1\s\src\coreclr\src\dlls\mscoree\unixinterface.cpp @ 326] 
0c 000000f8`2377efd0 00007ffe`cf948de7     : 00000237`2218a6d8 00000000`00000000 00007ffe`cf9a63b0 00000237`2218a6d8 : hostpolicy+0x18c03
0d 000000f8`2377f160 00007ffe`cf9497eb     : 00000000`00000000 00000000`00000000 000000f8`2377f2a0 00000000`00000000 : hostpolicy+0x18de7
0e 000000f8`2377f1a0 00007fff`14063ba2     : 000000f8`2377f4b8 000000f8`2377f4b8 00000000`00000000 00000000`00000000 : hostpolicy!corehost_main+0xfb
0f 000000f8`2377f360 00007fff`140673d8     : 00000237`221a6d00 00000000`00000000 00000000`00000000 00000000`00000000 : hostfxr!hostfxr_close+0x7d2
10 000000f8`2377f440 00007fff`14065d63     : 000000f8`2377f6b0 000000f8`2377f621 00000000`00000001 000000f8`2377f6d0 : hostfxr!hostfxr_close+0x4008
11 000000f8`2377f530 00007fff`140620f9     : 000000f8`2377f6d0 00000237`221a4e70 00000000`00000001 00007fff`351dea0b : hostfxr!hostfxr_close+0x2993
12 000000f8`2377f670 00007ff6`c93ce274     : 00000000`00000008 00000237`221a4e70 00000000`00000008 00007fff`140629d0 : hostfxr!hostfxr_main_startupinfo+0x89
13 000000f8`2377f770 00007ff6`c93ce6ac     : 00007ff6`c93dc6b0 00000000`00000007 00000000`00000000 00000000`0000005e : testStart_exe+0xe274
14 000000f8`2377f950 00007ff6`c93d0288     : 00000000`00000000 00000000`00000000 00000237`2218a6d0 00000000`00000000 : testStart_exe+0xe6ac
15 000000f8`2377fac0 00007fff`35cb6fd4     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : testStart_exe+0x10288
16 000000f8`2377fb00 00007fff`379bcec1     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : KERNEL32! 
17 000000f8`2377fb30 00000000`00000000     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!

To fix this for your app, you should either use Build().Run() or do something like:

using var host = ....Start();
host.WaitForShutdown();
// or await host.WaitForShutdownAsync();

[sdmaclea]

To fix this for your app, you should either use Build().Run()

I can't seem to find a reference to the Start method in the docs

Closing this as per @josalem Start() isn't a public API.

[hoyosjs]

It is a public API: https://docs.microsoft.com/en-us/dotnet/api/microsoft.extensions.hosting.hostingabstractionshostextensions.start?view=dotnet-plat-ext-3.1#Microsoft_Extensions_Hosting_HostingAbstractionsHostExtensions_Start_Microsoft_Extensions_Hosting_IHost_

That being said, it's called out as synchronous. The main thread needs to block on it and dispose it, and logs a warning pointing at the solution otherwise.

[sdmaclea]

The docs seem inadequate. I made a comment on the doc. Used to be able to open an issue, but for some reason I don't see that option anymore.

[matthewrk]

No problems using Build().Run(), in fact the reason I was trying to access diagnostics in the first place was to debug a memory leak which this also solves so I assume it was breaking something to do with that too.

I may have picked the use of Start up from Intellisense as when you're at "CreateHostBuilder(args)." (which returns an IHostBuilder) the options amongst others are Start, StartAsync and Build with the tooltip of Start saying "Builds and starts the host" so that looks like the obvious way forward from there. All of the official documentation and samples use Build().Run() though so that's my error.

Thanks all, appreciate the help!

[davidfowl]

The docs seem inadequate. I made a comment on the doc. Used to be able to open an issue, but for some reason I don't see that option anymore.

The API docs for these leave much to be desired.. Hopefully we'll be fixing this soon.