Logging isnt shown and exception isnt thrown when using aspnet:6.0.13-alpine3.17-amd64

[TordS]

Describe the Bug

While using aspnet:6.0.13-alpine3.17-amd64 as a baseimage and throwing an exception in program.cs, we got exit code 139 without any logging.

using aspnet:6.0.13-alpine3.16-amd64 shows thrown exception

Steps to Reproduce

1. Create a ASPNET solution
2. Add docker support
3. Change base image to aspnet:6.0.13-alpine3.17-amd64
4. Throw exception early in program.cs
5. Start project using docker
6. See that exception isnt thrown and docker container isnt showing anything

Example project https://github.com/TordS/TestBaseImageException.git

Output of docker version

Client:
Cloud integration: v1.0.29
Version: 20.10.21
API version: 1.41
Go version: go1.18.7
Git commit: baeda1f
Built: Tue Oct 25 18:08:16 2022
OS/Arch: windows/amd64
Context: default
Experimental: true

Server: Docker Desktop 4.14.1 (91661)
Engine:
Version: 20.10.21
API version: 1.41 (minimum version 1.12)
Go version: go1.18.7
Git commit: 3056208
Built: Tue Oct 25 18:00:19 2022
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: 1.6.9
GitCommit: 1c90a442489720eec95342e1789ee8a5e1b9536f
runc:
Version: 1.1.4
GitCommit: v1.1.4-0-g5fd4c4d
docker-init:
Version: 0.19.0
GitCommit: de40ad0

Output of docker info

Client:
Context: default
Debug Mode: false
Plugins:
buildx: Docker Buildx (Docker Inc., v0.9.1)
compose: Docker Compose (Docker Inc., v2.12.2)
dev: Docker Dev Environments (Docker Inc., v0.0.3)
extension: Manages Docker extensions (Docker Inc., v0.2.13)
sbom: View the packaged-based Software Bill Of Materials (SBOM) for an image (Anchore Inc., 0.6.0)
scan: Docker Scan (Docker Inc., v0.21.0)

Server:
Containers: 1
Running: 1
Paused: 0
Stopped: 0
Images: 162
Server Version: 20.10.21
Storage Driver: overlay2
Backing Filesystem: extfs
Supports d_type: true
Native Overlay Diff: true
userxattr: false
Logging Driver: json-file
Cgroup Driver: cgroupfs
Cgroup Version: 1
Plugins:
Volume: local
Network: bridge host ipvlan macvlan null overlay
Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
Swarm: inactive
Runtimes: io.containerd.runtime.v1.linux runc io.containerd.runc.v2
Default Runtime: runc
Init Binary: docker-init
containerd version: 1c90a442489720eec95342e1789ee8a5e1b9536f
runc version: v1.1.4-0-g5fd4c4d
init version: de40ad0
Security Options:
seccomp
Profile: default
Kernel Version: 5.10.102.1-microsoft-standard-WSL2
Operating System: Docker Desktop
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 5.795GiB
Name: docker-desktop
ID: 4CGJ:WD2F:RORI:I3M6:ZPJK:DSSE:YG7J:7EEL:E5OP:GKKN:JRSC:EX5N
Docker Root Dir: /var/lib/docker
Debug Mode: false
HTTP Proxy: http.docker.internal:3128
HTTPS Proxy: http.docker.internal:3128
No Proxy: hubproxy.docker.internal
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
hubproxy.docker.internal:5000
127.0.0.0/8
Live Restore Enabled: false

WARNING: No blkio throttle.read_bps_device support
WARNING: No blkio throttle.write_bps_device support
WARNING: No blkio throttle.read_iops_device support
WARNING: No blkio throttle.write_iops_device support

[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.

[mthalman]

Having the exception throw at this point in the program causes a segfault for some reason. I've attached a core dump: core.zip. Moving this issue to dotnet/runtime to investigate.

[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.

[am11]

This enables command line debugging in the repro container: am11/TestBaseImageException@39bea0a:

$ git clone https://github.com/am11/TestBaseImageException
$ cd TestBaseImageException/TestBaseImageException/TestBaseImageException
$ docker build -f Dockerfile .. -t test42
$ docker run -it test42

# inside the container run lldb with aslr disabled
$ lldb dotnet TestBaseImageException.dll -o "settings set target.disable-aslr false"

(lldb) r
Process 45 launched: '/usr/bin/dotnet' (x86_64)
[1287/1290] Manually indexing DWARF for libcoreclr.so...
Process 45 stopped
* thread #1, name = 'dotnet', stop reason = signal SIGSEGV: invalid address (fault address: 0x0)
    frame #0: 0x00007fdb7f6bc468 libcoreclr.so`VirtualCallStubManager::predictStubKind(this=<unavailable>, stubStartAddress=32762622372701231) at virtualcallstubcpu.hpp:887:26

(lldb) clrstack -f
OS Thread Id: 0x2d (1)
        Child SP               IP Call Site
00007FFDC718B000 00007FDB7F6BC468 libcoreclr.so!VirtualCallStubManager::predictStubKind(unsigned long) + 168 at /__w/1/s/src/coreclr/vm/amd64/virtualcallstubcpu.hpp:887
00007FFDC718B070 00007FDB7F6C4D42 libcoreclr.so!VirtualCallStubManager::getStubKind(unsigned long, int) + 34 at /__w/1/s/src/coreclr/vm/virtualcallstub.h:345
00007FFDC718B090 00007FDB7F6BFB4F libcoreclr.so!VirtualCallStubManager::FindStubManager(unsigned long, VirtualCallStubManager::StubKind*, int) + 95 at /__w/1/s/src/coreclr/vm/virtualcallstub.cpp:988
00007FFDC718B0E0 00007FDB7F807ECE libcoreclr.so!AdjustContextForVirtualStub(_EXCEPTION_RECORD*, _CONTEXT*) + 78 at /__w/1/s/src/coreclr/vm/amd64/excepamd64.cpp:0
00007FFDC718B120 00007FDB7F7FEB0E libcoreclr.so!UnwindManagedExceptionPass1(PAL_SEHException&, _CONTEXT*) + 542 at /__w/1/s/src/coreclr/vm/exceptionhandling.cpp:4690
00007FFDC718B740 00007FDB7F7FEDA3 libcoreclr.so!DispatchManagedException(PAL_SEHException&, bool) + 67 at /__w/1/s/src/coreclr/vm/exceptionhandling.cpp:0
00007FFDC718BC40 00007FDB7F752F4D libcoreclr.so!IL_Throw(Object*) + 541 at /__w/1/s/src/coreclr/vm/jithelpers.cpp:0
00007FFDC718BC50                  [HelperMethodFrame: 00007ffdc718bc50] 
00007FFDC718BDD0 00007FDB064D2E60 TestBaseImageException.dll!Program.<Main>$(System.String[]) + 112 [/src/TestBaseImageException/Program.cs @ 5]
00007FFDC718BE10 00007FDB7F8A0443 libcoreclr.so!CallDescrWorkerInternal + 124 at /__w/1/s/src/coreclr/pal/inc/unixasmmacrosamd64.inc:854
00007FFDC718BE30 00007FDB7F6E3759 libcoreclr.so!MethodDescCallSite::CallTargetWorker(unsigned long const*, unsigned long*, int) + 1529 at /__w/1/s/src/coreclr/pal/inc/pal.h:4652
00007FFDC718BE30 00007FDB7F6E36FB libcoreclr.so!MethodDescCallSite::CallTargetWorker(unsigned long const*, unsigned long*, int) + 1435 at /__w/1/s/src/coreclr/vm/threads.inl:42
00007FFDC718C010 00007FDB7F5BE75A libcoreclr.so!RunMain(MethodDesc*, short, int*, PtrArray**) + 890 at /__w/1/s/src/coreclr/vm/callhelpers.h:0
00007FFDC718C010 00007FDB7F5BE751 libcoreclr.so!RunMain(MethodDesc*, short, int*, PtrArray**) + 881 at /__w/1/s/src/coreclr/vm/callhelpers.h:458
00007FFDC718C010 00007FDB7F5BE5DA libcoreclr.so!RunMain(MethodDesc*, short, int*, PtrArray**) + 506 at /__w/1/s/src/coreclr/vm/assembly.cpp:1455
00007FFDC718C010 00007FDB7F5BE5DA libcoreclr.so!RunMain(MethodDesc*, short, int*, PtrArray**) + 506 at /__w/1/s/src/coreclr/vm/assembly.cpp:1455
00007FFDC718C010 00007FDB7F5BE5C7 libcoreclr.so!RunMain(MethodDesc*, short, int*, PtrArray**) + 487 at /__w/1/s/src/coreclr/vm/clrex.inl:24
00007FFDC718C220 00007FDB7F5BEAB1 libcoreclr.so!Assembly::ExecuteMainMethod(PtrArray**, int) + 401 at /__w/1/s/src/coreclr/vm/assembly.cpp:0
00007FFDC718C4B0 00007FDB7F5F2553 libcoreclr.so!CorHost2::ExecuteAssembly(unsigned int, char16_t const*, int, char16_t const**, unsigned int*) + 643 at /__w/1/s/src/coreclr/vm/corhost.cpp:385
00007FFDC718C590 00007FDB7F5A8175 libcoreclr.so!coreclr_execute_assembly + 197 at /__w/1/s/src/coreclr/dlls/mscoree/unixinterface.cpp:0
00007FFDC718C5F0 00007FDB7FCD0BA5 libhostpolicy.so!run_app_for_context(hostpolicy_context_t const&, int, char const**) + 1301 at /root/runtime/src/native/corehost/hostpolicy/hostpolicy.cpp:255
00007FFDC718C6C0 00007FDB7FCD1709 libhostpolicy.so!corehost_main + 297 at /root/runtime/src/native/corehost/hostpolicy/hostpolicy.cpp:0
00007FFDC718C6C0 00007FDB7FCD16E9 libhostpolicy.so!corehost_main + 265 at /root/runtime/src/native/corehost/hostpolicy/hostpolicy.cpp:280
00007FFDC718C850 00007FDB7FD1786D libhostfxr.so!fx_muxer_t::handle_exec_host_command(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, host_startup_info_t const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, std::unordered_map<known_options, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>, known_options_hash, std::equal_to<known_options>, std::allocator<std::pair<known_options const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>>>> const&, int, char const**, int, host_mode_t, bool, char*, int, int*) + 1741 at /root/runtime/src/native/corehost/fxr/fx_muxer.cpp:0
00007FFDC718C850 00007FDB7FD17602 libhostfxr.so!fx_muxer_t::handle_exec_host_command(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, host_startup_info_t const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, std::unordered_map<known_options, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>, known_options_hash, std::equal_to<known_options>, std::allocator<std::pair<known_options const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>>>> const&, int, char const**, int, host_mode_t, bool, char*, int, int*) + 1122 at /usr/include/c++/10.2.1/bits/unique_lock.h:66
00007FFDC718C850 00007FDB7FD174FD libhostfxr.so!fx_muxer_t::handle_exec_host_command(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, host_startup_info_t const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&, std::unordered_map<known_options, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>, known_options_hash, std::equal_to<known_options>, std::allocator<std::pair<known_options const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>>>> const&, int, char const**, int, host_mode_t, bool, char*, int, int*) + 861 at /root/runtime/src/native/corehost/fxr/fx_muxer.cpp:531
00007FFDC718C990 00007FDB7FD16483 libhostfxr.so!fx_muxer_t::execute(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, int, char const**, host_startup_info_t const&, char*, int, int*) + 771 at /root/runtime/src/native/corehost/fxr/fx_muxer.cpp:579
00007FFDC718CAC0 00007FDB7FD129E8 libhostfxr.so!hostfxr_main_startupinfo + 200 at /root/runtime/src/native/corehost/fxr/hostfxr.cpp:0
00007FFDC718CB90 000055FA905C691F dotnet!exe_start(int, char const**) + 1167 at /root/runtime/src/native/corehost/corehost.cpp:0
00007FFDC718CCE0 000055FA905C6B60 dotnet!main + 144 at /root/runtime/src/native/corehost/corehost.cpp:301
00007FFDC718CD20 00007FDB7FFF59CA ld-musl-x86_64.so.1 + -1

cc @janvorli

[janvorli]

The issue is due to a problem unwinding out of the frame at the bottom of the stack above, the ld-musl-x86_64.so.1 + -1. The libunwind unwinds from that frame to some unknown address and keeps going from there until it reaches an address that is in unmapped memory and so the VirtualCallStubManager::predictStubKind fails to read from that memory and the process exits with SIGSEGV.
Stepping through the libunwind code, we reach the code path here:

runtime/src/coreclr/pal/src/libunwind/src/x86_64/Gstep.c

Lines 95 to 105 in 56c8497

	/* DWARF failed. There isn't much of a usable frame-chain on x86-64,
	but we do need to handle two special-cases:
	(i) signal trampoline: Old kernels and older libcs don't
	export the vDSO needed to get proper unwind info for the
	trampoline. Recognize that case by looking at the code
	and filling in things by hand.
	(ii) PLT (shared-library) call-stubs: PLT stubs are invoked
	via CALLQ. Try this for all non-signal trampoline
	code. */

That tries to fall back to frame chain unwinding (RBP chain in the x64 case). But there is no RBP chain there, so we walk through some bogus RBP ultimately reaching unreadable memory.

[am11]

A similar issue was fixed in libunwind/libunwind@b5cd210. We can try applying that patch?

I have a branch with libunwind 1.7.0-rc2 changes (https://github.com/am11/runtime/tree/feature/vendor/update-libunwind) waiting for 1.7 final cut before sending out the PR.

[janvorli]

@am11 this is .NET 6.0 and it uses libunwind v1.5-rc1-28-g9165d2a1. I wonder if we should really go all the way to backporting 1.7.0. I am actually considering a surgical fix. We could possibly declare an exception unhandled if we reach the coreclr_execute_assembly or coreclr_initialize. That would safe us from the issues of unwinding out of the bottom of the stack.

[am11]

Sounds great. (I wasn't thinking about backporting the entire release 😅 just cherry-picking the commits which are already pushed to their main if possible)

[janvorli]

FYI, the issue is with Alpine 3.17 only. I've tried it with the aspnet:6.0.13-alpine3.16-amd64 image and it worked correctly.

[janvorli]

@am11 I've tried to cherry pick the change you've mentioned and it didn't fix the problem. I've also just found that the same issue happens in .NET 7.