I get a handle when running .NET Core (linux-x64 particularly) 2.1.3 (using the 2.1.401 SDK). When launching pseudo and running "dotnet --version", the hang happens immediately. I initially opened an issue with the Microsoft team, but they are suggesting (and it does it indeed look like) that it is a bug in pseudo. I am using Yocto (sumo) with pseudo version 1.9.0 (fddbe854c9db058d5a05830d3bcdd4233d95ee2e). Here is the original issue I opened with the Microsoft team. https://github.com/dotnet/coreclr/issues/19682 I need this to work so that I can create Yocto recipes that build/deploy .NET Core applications.
Thread 4 (LWP 750): #0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135 No locals. #1 0x000000369ee09a85 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x7ff11fe391c0 <pseudo_mutex>) at /usr/src/debug/glibc/2.27-r0/git/nptl/pthread_mutex_lock.c:78 type = 0 __PRETTY_FUNCTION__ = "__pthread_mutex_lock" id = <optimized out> #2 0x00007ff11fbfc46e in pseudo_getlock () at /usr/src/debug/pseudo/1.9.0+gitAUTOINC+fddbe854c9-r0/git/pseudo_wrappers.c:232 No locals. #3 0x00007ff11fc041c2 in close (fd=12) at /usr/src/debug/pseudo/1.9.0+gitAUTOINC+fddbe854c9-r0/git/pseudo_wrapfuncs.c:1833 saved = {__val = {0, 0, 0, 0, 0, 0, 0, 7771196, 0, 7771152, 140671453228688, 8, 140721121120655, 1, 7771112, 234593781177}} rc = -1 save_errno = <optimized out> #4 0x00007ff11f346f2b in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #5 0x00007ff11f345999 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #6 0x000000369ee07477 in start_thread (arg=0x7ff09ffff700) at /usr/src/debug/glibc/2.27-r0/git/nptl/pthread_create.c:463 pd = 0x7ff09ffff700 now = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140671453230848, -5511970289552424946, 140721121120654, 140721121120655, 8396800, 140721121120824, 5503596409520685070, -5481810962224349170}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}} not_first_call = <optimized out> #7 0x000000369eaf208f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 No locals. Thread 3 (LWP 749): #0 0x000000369eae3f68 in __libc_openat64 (fd=-100, file=0x62f270 "/tmp/clr-debug-pipe-747-4947-in", oflag=0) at /usr/src/debug/glibc/2.27-r0/git/sysdeps/unix/sysv/linux/openat64.c:45 resultvar = 18446744073709551104 sc_cancel_oldtype = 0 mode = 0 #1 0x00007ff11fbfb300 in wrap_openat (dirfd=dirfd@entry=-100, path=0x62f270 "/tmp/clr-debug-pipe-747-4947-in", flags=flags@entry=0) at /usr/src/debug/pseudo/1.9.0+gitAUTOINC+fddbe854c9-r0/git/ports/linux/guts/openat.c:72 rc = -1 ap = {{gp_offset = 24, fp_offset = 0, overflow_arg_area = 0x7ff0a4a24630, reg_save_area = 0x7ff0a4a245c0}} mode = 0 buf = {st_dev = 0, st_ino = 1535339371, st_nlink = 770153037, st_mode = 1535339371, st_uid = 0, st_gid = 770153037, __pad0 = 0, st_rdev = 1535339371, st_size = 770153037, st_blksize = 0, st_blocks = 0, st_atim = {tv_sec = 0, tv_nsec = 0}, st_mtim = {tv_sec = 6484592, tv_nsec = 0}, st_ctim = {tv_sec = 140671530980960, tv_nsec = 7744512}, __glibc_reserved = {6484592, 4096, 140673596637077}} existed = 1 save_errno = <optimized out> #2 0x00007ff11fbfb4da in wrap_open (path=<optimized out>, flags=flags@entry=0) at /usr/src/debug/pseudo/1.9.0+gitAUTOINC+fddbe854c9-r0/git/ports/linux/guts/open.c:10 ap = {{gp_offset = 16, fp_offset = 32753, overflow_arg_area = 0x7ff0a4a24690, reg_save_area = 0x7ff0a4a24650}} #3 0x00007ff11fc1004c in open (path=<optimized out>, flags=0) at /usr/src/debug/pseudo/1.9.0+gitAUTOINC+fddbe854c9-r0/git/pseudo_wrapfuncs.c:9534 saved = {__val = {0 <repeats 16 times>}} ap = {{gp_offset = 16, fp_offset = 0, overflow_arg_area = 0x7ff0a4a247b0, reg_save_area = 0x7ff0a4a24740}} mode = 0 rc = -1 save_errno = <optimized out> __func__ = "open" #4 0x00007ff11f249d9f in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #5 0x00007ff11f242a78 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #6 0x00007ff11f241929 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #7 0x00007ff11f345a62 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #8 0x000000369ee07477 in start_thread (arg=0x7ff0a4a25700) at /usr/src/debug/glibc/2.27-r0/git/nptl/pthread_create.c:463 pd = 0x7ff0a4a25700 now = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140671530981120, -5511970289552424946, 140721121120094, 140721121120095, 8396800, 140721121120264, 5503615886123630606, -5481810962224349170}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}} not_first_call = <optimized out> #9 0x000000369eaf208f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 No locals. Thread 2 (LWP 748): #0 0x000000369eae82b9 in __GI___poll (fds=0x7ff0a5245e28, nfds=1, timeout=-1) at /usr/src/debug/glibc/2.27-r0/git/sysdeps/unix/sysv/linux/poll.c:29 resultvar = 18446744073709551100 sc_cancel_oldtype = 0 #1 0x00007ff11f33d403 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #2 0x00007ff11f33c963 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #3 0x00007ff11f345a62 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #4 0x000000369ee07477 in start_thread (arg=0x7ff0a5246700) at /usr/src/debug/glibc/2.27-r0/git/nptl/pthread_create.c:463 pd = 0x7ff0a5246700 now = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140671539504896, -5511970289552424946, 140721121120862, 140721121120863, 8396800, 140721121121032, 5503616933558779918, -5481810962224349170}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}} not_first_call = <optimized out> #5 0x000000369eaf208f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 No locals. Thread 1 (LWP 747): #0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135 No locals. #1 0x000000369ee09a85 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x7ff11fe391c0 <pseudo_mutex>) at /usr/src/debug/glibc/2.27-r0/git/nptl/pthread_mutex_lock.c:78 type = 0 __PRETTY_FUNCTION__ = "__pthread_mutex_lock" id = <optimized out> #2 0x00007ff11fbfc46e in pseudo_getlock () at /usr/src/debug/pseudo/1.9.0+gitAUTOINC+fddbe854c9-r0/git/pseudo_wrappers.c:232 No locals. #3 0x00007ff11fc07a4a in fopen64 (path=0x7ffc306fd0b0 "/proc/747/stat", mode=0x7ff11f3cd913 "r") at /usr/src/debug/pseudo/1.9.0+gitAUTOINC+fddbe854c9-r0/git/pseudo_wrapfuncs.c:4067 saved = {__val = {0, 3904960854615930675, 8458434531088821347, 747, 0, 140721121120904, 6367331215889861981, 6435167007366008321, 0, 0, 0, 0, 0, 0, 0, 0}} rc = 0x0 save_errno = <optimized out> __func__ = "fopen64" #4 0x00007ff11f342e88 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #5 0x00007ff11f342d4d in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #6 0x00007ff11f21d7d4 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #7 0x00007ff11efe058b in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #8 0x00007ff11efdfb95 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #9 0x00007ff11efdfa1a in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #10 0x00007ff11ef28919 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #11 0x00007ff11ef03aad in coreclr_initialize () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libcoreclr.so No symbol table info available. #12 0x00007ff11f6db780 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libhostpolicy.so No symbol table info available. #13 0x00007ff11f6cdcfb in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libhostpolicy.so No symbol table info available. #14 0x00007ff11f6ceb4c in corehost_main () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/shared/Microsoft.NETCore.App/2.1.3/libhostpolicy.so No symbol table info available. #15 0x00007ff11f981cbf in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/host/fxr/2.1.3/libhostfxr.so No symbol table info available. #16 0x00007ff11f98d36c in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/host/fxr/2.1.3/libhostfxr.so No symbol table info available. #17 0x00007ff11f98e4c5 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/host/fxr/2.1.3/libhostfxr.so No symbol table info available. #18 0x00007ff11f98e5a9 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/host/fxr/2.1.3/libhostfxr.so No symbol table info available. #19 0x00007ff11f98e155 in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/host/fxr/2.1.3/libhostfxr.so No symbol table info available. #20 0x00007ff11f98d9aa in ?? () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/host/fxr/2.1.3/libhostfxr.so No symbol table info available. #21 0x00007ff11f981f0c in hostfxr_main_startupinfo () from /opt/medxchange/2.5/sysroots/corei7-64-poky-linux/usr/share/dotnet/host/fxr/2.1.3/libhostfxr.so No symbol table info available. #22 0x000000000040ac74 in ?? () No symbol table info available. #23 0x000000000040af05 in ?? () No symbol table info available. #24 0x000000369ea21a57 in __libc_start_main (main=0x40ae60, argc=2, argv=0x7ffc306ff078, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffc306ff068) at /usr/src/debug/glibc/2.27-r0/git/csu/libc-start.c:308 result = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {0, -5511969730755788786, 4229675, 140721121128560, 0, 0, 5510696093563256846, -5481811493393104882}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x7ffc306ff090, 0x369e826110}, data = {prev = 0x0, cleanup = 0x0, canceltype = 812642448}}} not_first_call = <optimized out> #25 0x0000000000408a54 in _start () No symbol table info available.
This is similar to another reported issue. https://bugzilla.yoctoproject.org/show_bug.cgi?id=12857 However, my coreclr doesn't have lttng on. It is def not the issue. There is something with how .NET Core is creating a debug pipe (in /tmp directory) and assessing /proc/{procid}/stat. using "export COMPlus_EnableDiagnostics=0" before running .NET fixes this issue.
Thanks! I think you're right that lttng is a red herring. So looking at this, it looks like the fopen() call is blocking waiting for the openat() call to complete. So something in libcoreclr.so is calling open(), and something in libhostfxr is calling fopen(), and something in libcoreclr is calling close(). What I don't understand is why libc_openat64 is blocking, but possibly it's relevant that the file's name is "clr-debug-pipe-747-4947-in"... Ah-hah! If you open a named pipe, without O_NONBLOCK, and you are opening it only for reading, the open blocks until a writer has opened the pipe for writing. And the same happens with opening the file for writing-only. So if you have two threads trying to open a pipe for reading and writing, we have the problem of (possibly apocryphal) legislation concerning cars at an intersection: Each must come to a complete stop, and not begin to move again until there are no other cars present. The problem is, we could "fix" this by forcing the read-only open to have O_NONBLOCK... But only if we could be sure that the read-only one happened first, which we can't. I'll think about this. I am open to suggestions.
Thanks! I think you're right that lttng is a red herring. So looking at this, it looks like the fopen() call is blocking waiting for the openat() call to complete. So something in libcoreclr.so is calling open(), and something in libhostfxr is calling fopen(), and something in libcoreclr is calling close(). What I don't understand is why libc_openat64 is blocking, but possibly it's relevant that the file's name is "clr-debug-pipe-747-4947-in"... Ah-hah! If you open a named pipe, without O_NONBLOCK, and you are opening it only for reading, the open blocks until a writer has opened the pipe for writing. And the same happens with opening the file for writing-only. So if you have two threads trying to open a pipe for reading and writing, we have the problem of (possibly apocryphal) legislation concerning cars at an intersection: Each must come to a complete stop, and not begin to move again until there are no other cars present. The problem is, we could "fix" this by forcing the read-only open to have O_NONBLOCK... But only if we could be sure that the read-only one happened first, which we can't. I'll think about this. I am open to suggestions. My basic thought is that we should probably figure out a way to try to allow dropping the lock right before open, and then acquiring it right after the open.
gah, sorry about mostly-duplicative comment, firefox is helping
I had an idea about how to do this, but it seemed difficult, but I went and looked at the code, and it turns out part of the problem was Previously Solved for the exec* case, and leveraging that, I could implement something which at least works in the trivial case and apparently doesn't crash. Have pushed a patch to pseudo master.
Any update?
I have a patch pushed to master, but not an easy way to test it from here. Or if I do, I don't know what the easy way to test it is. Imagine for the sake of argument that I have no information about .NET; is there a trivial reproducer I could run to confirm/deny the thing?
*** Bug 12857 has been marked as a duplicate of this bug. ***
Paul, Peter asked, "is there a trivial reproducer I could run to confirm/deny the thing?" Do you have such a test case or have you tested Peter's change? ../Randy
Testing results are not reported but apparently fixed.