Re: LD_DEBUG crashes applications

[Diego Nieto Cid]

Hello,

One more update.

On Wed, Apr 13, 2016 at 10:58:18PM -0300, Diego Nieto Cid wrote:
> 
> So, it looks like '_hurd_intr_rpc_mach_msg' is not being corretly
> resolved in the loader's code, right? Although, I'm puzzled about why
> all the previous messages were printed successfully.
>

What's happening is that, at the beginning, that function is resolved to
an implementation provided by the dynamic loader; this is the
self-relocation at elf/rtld.c:397 I mentioned in the getpid thread.

Then, the symbol binding process starts and debug information is printed
using the implementation mentioned above. When '_hurd_intr_rpc_mach_msg'
is bound the implementation is replaced by the one provided by libc.

The new version is in libc's code section which references its own PLT to
call the functions it needs; and due to lazy binding the symbols in libc
still reference the stub (which calls into the dynamic loader).

While the next symbol is bound and '_dl_lookup_symbol_x' tries to print the
debugging message, the libc '_hurd_intr_rpc_mach_msg' is called which
eventually calls '__mach_msg@plt' and that leads, through the stub, to the
symbol resolution process in the dynamic linker; therefore back to
'_dl_lookup_symbol_x' and to printing.

I tried the obvious workaround, not printing anything when binding
'__mach_msg', like the following patch:

@@ -937,6 +944,14 @@ _dl_lookup_symbol_x (const char *undef_n

   if (__glibc_unlikely (GLRO(dl_debug_mask)
                        & (DL_DEBUG_BINDINGS|DL_DEBUG_PRELINK)))
+  /* XXX Printing debug messages relies on a properly setup
+         __mach_msg symbol.
+         If we are looking for that symbol, it may be possible
+         that the relocation in progress was triggered by
+         its lazy loading; which means printing will lead us
+         here idefinitely. */
+  if (strcmp (undef_name, "__mach_msg") != 0)
+
     _dl_debug_bindings (undef_name, undef_map, ref,
                        &current_value, version, type_class, protected);

but that only caused more strange behaviours, now in the signal thread[1].

The pattern is the same though: some function needed for printing is being
loaded triggering more printing.

One idea that comes to mind for fixing this issue is to print the debugging
message after the PLT is updated; thus calling the print function will find
the symbol already resolved and will proceed to the next dependency until
no more symbols need to be bound. The stack will unwind printing all the
pending messages and hopefully the recursion is now limited.
On my mind it should work :p

I guess it's easier said than done; more so considering other targets
don't need this dance at all.

Another idea is to use functions provided exclusively by the dynamic
linker to print messages; thus avoiding the problem of unbound
dependencies.

Regards,
Diego

---

[1] Running 'LD_DEBUG=bindings ls' with the patched libc hangs and attaching
gdb to the process reveals the following threads and backtraces. I haven't
investigated but it seems the signal thread manages to get into a recursion
like described above but this time while binding __mutex_lock_solid.

(gdb) info threads
  Id   Target Id         Frame
  2    Thread 1685.2     strcmp (p1=0x104dea7 "HURD_CTHREADS_0.3",
    p2=0x104dea7 "HURD_CTHREADS_0.3") at strcmp.c:27
* 1    Thread 1685.1     0x00017802 in __writev (fd=<optimized out>,
    iov=<optimized out>, niov=<optimized out>)
    at ../sysdeps/mach/hurd/dl-sysdep.c:429
(gdb) thread apply all bt

Thread 2 (Thread 1685.2):
#0  strcmp (p1=0x104dea7 "HURD_CTHREADS_0.3", p2=0x104dea7 "HURD_CTHREADS_0.3")
    at strcmp.c:27
#1  0x000095e0 in check_match (
    undef_name=undef_name@entry=0x1049a0e "__mutex_lock_solid",
    ref=ref@entry=0x104077c, version=version@entry=0x12392e0, flags=5,
    type_class=1, sym=0x104077c, symidx=907, strtab=0x1046f6c "",
    map=0x10327f0, versioned_sym=0x12750c0, num_versions=0x12750bc)
    at dl-lookup.c:138
#2  0x00009d71 in do_lookup_x (undef_name=<optimized out>,
    undef_name@entry=0x1049a0e "__mutex_lock_solid",
    new_hash=new_hash@entry=1233373816, old_hash=old_hash@entry=0x127514c,
    ref=0x104077c, result=0x1275154, scope=0x2bc14, i=1, version=0x12392e0,
    flags=5, skip=0x0, type_class=1, undef_map=0x10327f0) at dl-lookup.c:430
#3  0x0000a30b in _dl_lookup_symbol_x (
    undef_name=undef_name@entry=0x1049a0e "__mutex_lock_solid",
    undef_map=undef_map@entry=0x10327f0, ref=ref@entry=0x12751e0,
    symbol_scope=0x10329a8, version=0x12392e0, type_class=1, flags=5,
    skip_map=0x0) at dl-lookup.c:836
#4  0x0000f008 in _dl_fixup (l=0x10327f0, reloc_arg=<optimized out>)
    at dl-runtime.c:111
#5  0x00015c80 in _dl_runtime_resolve () at ../sysdeps/i386/dl-trampoline.S:43
#6  0x0106d110 in __mutex_lock (__lock=0x121e698 <_hurd_siglock>)
    at ../mach/lock-intern.h:88
#7  _hurd_thread_sigstate (thread=119) at hurdsig.c:78
#8  0x01073e56 in _hurd_self_sigstate () at ../hurd/hurd/signal.h:168
#9  _hurd_intr_rpc_msg_sp_restored () at intr-msg.c:91
#10 0x0001b121 in __io_write (io_object=6,
    data=0x1275b4c "         0:\tbinding file /lib/i386-gnu/libc.so.0.3 [0] to 
/lib/i386-gnu/libc.so.0.3 [0]: normal symbol `__mutex_lock_solid'",
    dataCnt=123, offset=-1, amount=0x1275be8)
    at 
/opt/stash/diego/src/debian/glibc/glibc-2.22/build-tree/hurd-i386-libc/hurd/RPC_io_write.c:171
#11 0x0001780a in __writev (fd=<optimized out>, iov=<optimized out>,
    niov=<optimized out>) at ../sysdeps/mach/hurd/dl-sysdep.c:429
#12 0x00010643 in _dl_writev (niov=14, iov=0x1275c9c, fd=2) at ./dl-writev.h:54
#13 _dl_debug_vdprintf (fd=2, tag_p=-1, tag_p@entry=1, fmt=0x22019 "",
    fmt@entry=0x21fe8 "binding file %s [%lu] to %s [%lu]: %s symbol `%s'",
    arg=0x1275ef8 "") at dl-misc.c:244
#14 0x00010a59 in _dl_debug_printf (
    fmt=0x21fe8 "binding file %s [%lu] to %s [%lu]: %s symbol `%s'")
    at dl-misc.c:255
#15 0x0000a723 in _dl_debug_bindings (protected=0, type_class=1,
    version=0x12392e0, value=0x1275f3c, ref=0x1275fc8, undef_map=0x10327f0,
    undef_name=0x1049a0e "__mutex_lock_solid") at dl-lookup.c:1020
#16 _dl_lookup_symbol_x (undef_name=<optimized out>,
    undef_name@entry=0x1049a0e "__mutex_lock_solid",
    undef_map=undef_map@entry=0x10327f0, ref=ref@entry=0x1275fc8,
    symbol_scope=0x10329a8, version=0x12392e0, type_class=1, flags=5,
    skip_map=0x0) at dl-lookup.c:955
#17 0x0000f008 in _dl_fixup (l=0x10327f0, reloc_arg=<optimized out>)
    at dl-runtime.c:111
#18 0x00015c80 in _dl_runtime_resolve () at ../sysdeps/i386/dl-trampoline.S:43
#19 0x0106d110 in __mutex_lock (__lock=0x121e698 <_hurd_siglock>)
    at ../mach/lock-intern.h:88
#20 _hurd_thread_sigstate (thread=119) at hurdsig.c:78
#21 0x01073e56 in _hurd_self_sigstate () at ../hurd/hurd/signal.h:168
#22 _hurd_intr_rpc_msg_sp_restored () at intr-msg.c:91
...

And goes on looking up for __mutex_lock_solid

...
#100 _hurd_intr_rpc_msg_sp_restored () at intr-msg.c:91
#101 0x0001b121 in __io_write (io_object=6,
    data=0x127bca4 "         0:\tbinding file /lib/i386-gnu/libc.so.0.3 [0] to 
/lib/i386-gnu/libc.so.0.3 [0]: normal symbol `__mutex_lock_solid'",
    dataCnt=123, offset=-1, amount=0x127bd40)
    at 
/opt/stash/diego/src/debian/glibc/glibc-2.22/build-tree/hurd-i386-libc/hurd/RPC_io_write.c:171
#102 0x0001780a in __writev (fd=<optimized out>, iov=<optimized out>,
    niov=<optimized out>) at ../sysdeps/mach/hurd/dl-sysdep.c:429
#103 0x00010643 in _dl_writev (niov=14, iov=0x127bdf4, fd=2)
    at ./dl-writev.h:54
#104 _dl_debug_vdprintf (fd=2, tag_p=-1, tag_p@entry=1, fmt=0x22019 "",
    fmt@entry=0x21fe8 "binding file %s [%lu] to %s [%lu]: %s symbol `%s'",
    arg=0x127c050 "") at dl-misc.c:244
#105 0x00010a59 in _dl_debug_printf (
    fmt=0x21fe8 "binding file %s [%lu] to %s [%lu]: %s symbol `%s'")
    at dl-misc.c:255
#106 0x0000a723 in _dl_debug_bindings (protected=0, type_class=1,
    version=0x12392e0, value=0x127c094, ref=0x127c120, undef_map=0x10327f0,
    undef_name=0x1049a0e "__mutex_lock_solid") at dl-lookup.c:1020
#107 _dl_lookup_symbol_x (undef_name=<optimized out>,
    undef_name@entry=0x1049a0e "__mutex_lock_solid",
    undef_map=undef_map@entry=0x10327f0, ref=ref@entry=0x127c120,
    symbol_scope=0x10329a8, version=0x12392e0, type_class=1, flags=5,
    skip_map=0x0) at dl-lookup.c:955
#108 0x0000f008 in _dl_fixup (l=0x10327f0, reloc_arg=<optimized out>)
    at dl-runtime.c:111
#109 0x00015c80 in _dl_runtime_resolve () at ../sysdeps/i386/dl-trampoline.S:43
#110 0x0106d110 in __mutex_lock (__lock=0x121e698 <_hurd_siglock>)
    at ../mach/lock-intern.h:88
#111 _hurd_thread_sigstate (thread=119) at hurdsig.c:78
#112 0x01073e56 in _hurd_self_sigstate () at ../hurd/hurd/signal.h:168
#113 _hurd_intr_rpc_msg_sp_restored () at intr-msg.c:91
#114 0x0001b121 in __io_write (io_object=6,
    data=0x127ca8c "         0:\tbinding file /lib/i386-gnu/libc.so.0.3 [0] to 
/lib/i386-gnu/libc.so.0.3 [0]: normal symbol `__mach_reply_port'", dataCnt=122,
    offset=-1, amount=0x127cb28)
    at 
/opt/stash/diego/src/debian/glibc/glibc-2.22/build-tree/hurd-i386-libc/hurd/RPC_io_write.c:171
#115 0x0001780a in __writev (fd=<optimized out>, iov=<optimized out>,
    niov=<optimized out>) at ../sysdeps/mach/hurd/dl-sysdep.c:429
#116 0x00010643 in _dl_writev (niov=14, iov=0x127cbdc, fd=2)
    at ./dl-writev.h:54
#117 _dl_debug_vdprintf (fd=2, tag_p=-1, tag_p@entry=1, fmt=0x22019 "",
    fmt@entry=0x21fe8 "binding file %s [%lu] to %s [%lu]: %s symbol `%s'",
    arg=0x127ce38 "") at dl-misc.c:244
#118 0x00010a59 in _dl_debug_printf (
    fmt=0x21fe8 "binding file %s [%lu] to %s [%lu]: %s symbol `%s'")
    at dl-misc.c:255
#119 0x0000a723 in _dl_debug_bindings (protected=0, type_class=1,
    version=0x1239150, value=0x127ce7c, ref=0x127cf08, undef_map=0x10327f0,
    undef_name=0x104d5ee "__mach_reply_port") at dl-lookup.c:1020
#120 _dl_lookup_symbol_x (undef_name=<optimized out>,
    undef_name@entry=0x104d5ee "__mach_reply_port",
    undef_map=undef_map@entry=0x10327f0, ref=ref@entry=0x127cf08,
    symbol_scope=0x10329a8, version=0x1239150, type_class=1, flags=5,
    skip_map=0x0) at dl-lookup.c:955
#121 0x0000f008 in _dl_fixup (l=0x10327f0, reloc_arg=<optimized out>)
    at dl-runtime.c:111
#122 0x00015c80 in _dl_runtime_resolve () at ../sysdeps/i386/dl-trampoline.S:43
#123 0x01057eaa in __mig_get_reply_port ()
    at ../sysdeps/mach/hurd/mig-reply.c:32
#124 0x0122a52c in __mach_port_mod_refs (task=1, name=119, right=0, delta=1)
    at 
/opt/stash/diego/src/debian/glibc/glibc-2.22/build-tree/hurd-i386-libc/mach/RPC_mach_port_mod_refs.c:135
#125 0x0106d0d8 in _hurd_thread_sigstate (thread=119) at hurdsig.c:126
#126 0x01068433 in _hurd_self_sigstate () at ../hurd/hurd/signal.h:168
#127 _hurd_msgport_receive () at msgportdemux.c:64
#128 0x66688b92 in ?? ()

Thread 1 (Thread 1685.1):
#0  0x00017802 in __writev (fd=<optimized out>, iov=<optimized out>,
    niov=<optimized out>) at ../sysdeps/mach/hurd/dl-sysdep.c:429
#1  0x00010643 in _dl_writev (niov=8, iov=0x102cb60, fd=2) at ./dl-writev.h:54
#2  _dl_debug_vdprintf (fd=2, tag_p=tag_p@entry=1, fmt=0x2065c "",
    fmt@entry=0x20649 "\ncalling init: %s\n\n",
    arg=0x102cda8 "\351E\a\001\250n!\001\254n!\001") at dl-misc.c:244
#3  0x00010a59 in _dl_debug_printf (fmt=0x20649 "\ncalling init: %s\n\n")
    at dl-misc.c:255
#4  0x0000fb60 in call_init (l=0x1032aa8, argc=argc@entry=2,
    argv=argv@entry=0x102ce34, env=0x102ce40) at dl-init.c:50
#5  0x0000fc40 in call_init (env=0x102ce40, argv=0x102ce34, argc=2,
    l=<optimized out>) at dl-init.c:30
#6  _dl_init (main_map=<optimized out>, argc=2, argv=0x102ce34, env=0x102ce40)
    at dl-init.c:120
#7  0x00001df7 in _dl_start_user () from /lib/ld.so
(gdb)