A problem shown in --nest-libcall while running a Qt program.

[honggyukim]

I've got the below error message when running a Qt QML program.

$ cd Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug

$ uftrace record --nest-libcall planets
QML debugging is enabled. Only use this in a safe environment.
Inconsistency detected by ld.so: ../elf/dl-runtime.c: 79: _dl_fixup: Assertion `ELFW(R_TYPE)(reloc->r_info) == ELF_MACHINE_JMP_SLOT' failed!

I found the glibc source code and it shows as follows:

 52 /* This function is called through a special trampoline from the PLT the
 53    first time each PLT entry is called.  We must perform the relocation
 54    specified in the PLT of the given shared object, and return the resolved
 55    function address to the trampoline, which will restart the original call
 56    to that address.  Future calls will bounce directly from the PLT to the
 57    function.  */
 58 
 59 DL_FIXUP_VALUE_TYPE
 60 __attribute ((noinline)) ARCH_FIXUP_ATTRIBUTE
 61 _dl_fixup (
 62 # ifdef ELF_MACHINE_RUNTIME_FIXUP_ARGS
 63            ELF_MACHINE_RUNTIME_FIXUP_ARGS,
 64 # endif
 65            struct link_map *l, ElfW(Word) reloc_arg)
 66 {
 67   const ElfW(Sym) *const symtab
 68     = (const void *) D_PTR (l, l_info[DT_SYMTAB]);
 69   const char *strtab = (const void *) D_PTR (l, l_info[DT_STRTAB]);
 70 
 71   const PLTREL *const reloc
 72     = (const void *) (D_PTR (l, l_info[DT_JMPREL]) + reloc_offset);
 73   const ElfW(Sym) *sym = &symtab[ELFW(R_SYM) (reloc->r_info)];
 74   void *const rel_addr = (void *)(l->l_addr + reloc->r_offset);
 75   lookup_t result;
 76   DL_FIXUP_VALUE_TYPE value;
 77 
 78   /* Sanity check that we're really looking at a PLT relocation.  */
 79   assert (ELFW(R_TYPE)(reloc->r_info) == ELF_MACHINE_JMP_SLOT);
 80 
 81    /* Look up the target symbol.  If the normal lookup rules are not
 82       used don't look in the global scope.  */
 83   if (__builtin_expect (ELFW(ST_VISIBILITY) (sym->st_other), 0) == 0)
 84     {
 85       const struct r_found_version *version = NULL;
 86 
 87       if (l->l_info[VERSYMIDX (DT_VERSYM)] != NULL)
 88         {
 89           const ElfW(Half) *vernum =
 90             (const void *) D_PTR (l, l_info[VERSYMIDX (DT_VERSYM)]);
 91           ElfW(Half) ndx = vernum[ELFW(R_SYM) (reloc->r_info)] & 0x7fff;
 92           version = &l->l_versions[ndx];
 93           if (version->hash == 0)
 94             version = NULL;
 95         }
                    ...

It works fine without --nest-libcall.

[honggyukim]

Here is the log output with -vv.

uftrace: removing uftrace.data.old directory
uftrace: creating 2 thread(s) for recording
uftrace: start writer thread 0
uftrace: start writer thread 1
uftrace: using libmcount.so library for tracing
mcount: initializing mcount library
symbol: loading symbols from /home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug/planets (offset: 0x556642c3d000)
symbol: loaded 34 symbols
        ...
mcount: found GOT at 0x7f8226201000 (PLT resolver: 0x7f822e9f9af0)
mcount: mcount setup done
mcount: preparing shmem buffers
uftrace: MSG SESSION: 26713: /home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug/planets (05602fc338ae8e64)
uftrace: MSG START: /uftrace-05602fc338ae8e64-26713-000
uftrace: MSG TASK_START : 26713/26713
QML debugging is enabled. Only use this in a safe environment.
uftrace: MSG DLOPEN: 26713: 0x7f8225808000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/platforms/libqxcb.so
mcount: preparing shmem buffers
        ...
uftrace: MSG START: /uftrace-05602fc338ae8e64-26713-000
uftrace: MSG DLOPEN: 26713: 0x7f822267e000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/xcbglintegrations/libqxcb-glx-integration.so
uftrace: MSG DLOPEN: 26713: 0x7f821795f000 /usr/lib/x86_64-linux-gnu/liblttng-ust-tracepoint.so.0
uftrace: MSG DLOPEN: 26713: 0x7f821795f000 /usr/lib/x86_64-linux-gnu/liblttng-ust-tracepoint.so.0
uftrace: MSG DLOPEN: 26713: 0x7f822242b000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/platformthemes/libqgtk3.so
        ...
uftrace: MSG DLOPEN: 26713: 0x5c49b9b libgail.so
uftrace: MSG DLOPEN: 26713: 0x5c76b17 libatk-bridge.so
mcount: exception thrown from [2]
mcount: exception returned at frame: 0x7ffdfab71100
mcount: [2] parent at 0x7ffdfab70c88
mcount: [1] parent at 0x7ffdfab71728
mcount: [2] exception returned
        ...
uftrace: MSG START: /uftrace-05602fc338ae8e64-26713-001
mcount: new buffer: [0] /uftrace-05602fc338ae8e64-26713-000
uftrace: MSG  END : /uftrace-05602fc338ae8e64-26713-001
uftrace: MSG START: /uftrace-05602fc338ae8e64-26713-000
uftrace: MSG DLOPEN: 26713: 0x7f820455c000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqgif.so
uftrace: MSG DLOPEN: 26713: 0x7f8204352000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqicns.so
uftrace: MSG DLOPEN: 26713: 0x7f820414a000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqico.so
uftrace: MSG DLOPEN: 26713: 0x5dcdb46 libqjp2.so
uftrace: MSG DLOPEN: 26713: 0x7f81ffdc1000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqjpeg.so
uftrace: MSG DLOPEN: 26713: 0x7f81ffbbb000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqsvg.so
uftrace: MSG DLOPEN: 26713: 0x7f81ff761000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqtga.so
uftrace: MSG DLOPEN: 26713: 0x7f81ff504000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqtiff.so
uftrace: MSG DLOPEN: 26713: 0x7f81ff2ff000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqwbmp.so
uftrace: MSG DLOPEN: 26713: 0x7f81ff07f000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/imageformats/libqwebp.so
mcount: setup jmpbuf rstack at 7ffdfab706b0 (3 entries)
mcount: setup jmpbuf rstack at 5566461f2950 (3 entries)
mcount: setup jmpbuf rstack at 5566461f2950 (3 entries)
mcount: new buffer: [1] /uftrace-05602fc338ae8e64-26713-001
uftrace: MSG  END : /uftrace-05602fc338ae8e64-26713-000
        ...
uftrace: MSG DLOPEN: 26713: 0x7f81fde47000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/bearer/libqconnmanbearer.so
uftrace: MSG DLOPEN: 26713: 0x7f81fdc31000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/bearer/libqgenericbearer.so
uftrace: MSG DLOPEN: 26713: 0x7f81fd9f5000 /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/plugins/bearer/libqnmbearer.so
mcount: new buffer: [0] /uftrace-05602fc338ae8e64-26713-000
uftrace: MSG  END : /uftrace-05602fc338ae8e64-26713-001
uftrace: MSG START: /uftrace-05602fc338ae8e64-26713-000
uftrace: MSG  END : /uftrace-05602fc338ae8e64-26722-000
mcount: new buffer: [1] /uftrace-05602fc338ae8e64-26722-001
uftrace: MSG START: /uftrace-05602fc338ae8e64-26722-001
mcount: new buffer: [1] /uftrace-05602fc338ae8e64-26726-001
uftrace: MSG  END : /uftrace-05602fc338ae8e64-26726-000
        ...
uftrace: MSG START: /uftrace-05602fc338ae8e64-26713-000
mcount: new buffer: [1] /uftrace-05602fc338ae8e64-26713-001
uftrace: MSG  END : /uftrace-05602fc338ae8e64-26713-000
uftrace: MSG START: /uftrace-05602fc338ae8e64-26713-001
mcount: new buffer: [0] /uftrace-05602fc338ae8e64-26713-000
uftrace: MSG  END : /uftrace-05602fc338ae8e64-26713-001
uftrace: MSG START: /uftrace-05602fc338ae8e64-26713-000
Inconsistency detected by ld.so: ../elf/dl-runtime.c: 79: _dl_fixup: Assertion `ELFW(R_TYPE)(reloc->r_info) == ELF_MACHINE_JMP_SLOT' failed!
uftrace: all process/thread exited
uftrace: child terminated with exit code: 127
uftrace: stop writer thread 1
uftrace: stop writer thread 0
uftrace: reading uftrace.data/task.txt file

[honggyukim]

$ uftrace replay
         ...
   0.033 us [ 6298] |           memset();
   0.041 us [ 6298] |           memset();
   0.042 us [ 6298] |           memcpy();
   0.031 us [ 6298] |           memset();
            [ 6298] |           QArrayData::allocate() {
   0.068 us [ 6298] |             malloc();
   0.199 us [ 6298] |           } /* QArrayData::allocate */
   0.036 us [ 6298] |           memset();
   0.032 us [ 6298] |           memset();

uftrace stopped tracing with remaining functions
================================================
task: 6298
[4] QObject::event
[3] QCoreApplication::notify
[2] g_main_context_iteration
[1] QCoreApplication::exec
[0] QGuiApplication::exec

task: 6308
[1] g_main_context_iteration
[0] QEventLoop::exec

task: 6310
[1] g_main_context_iteration
[0] QThread::exec

task: 6312
[0] g_main_context_iteration

[namhyung]

I think the assertion should not happen since all PLT functions have a JMP_SLOT relocation type. I'd like to know which function actually caused the assertion. Could you please rerun with -vvv and show what was the last function before the assertion? It'd be nice if you could find which module has it based on the module id printed.

[honggyukim]

I've tested it again but got the below different error log.

$ uftrace --version
uftrace v0.8.2-56-g06ee8

$ uftrace record --nest-libcall -v planets                                                                                                                                                
uftrace: removing uftrace.data.old directory
uftrace: skipping perf event due to error: Permission denied
uftrace: please check /proc/sys/kernel/perf_event_paranoid
uftrace: creating 2 thread(s) for recording
uftrace: using libmcount.so library for tracing
mcount: initializing mcount library
mcount: setup PLT hooking (nest-libcall)
mcount: mcount setup done
mcount: new session started: 37708c16716fd16d: planets
QML debugging is enabled. Only use this in a safe environment.
mcount: exception thrown from [2]
Segmentation fault: address not mapped (addr: 0xffffffffffffff90)
Backtrace from uftrace:
=====================================
[3] (__cxa_current_exception_type[7f6ac553b370] <= __gnu_cxx::__verbose_terminate_handler[7f6ac5543431])
[2] (std::terminate[7f6ac553d660] <= <7f6ac5541579>[7f6ac5541579])
[1] (QCoreApplicationPrivate::init[7f6ac662ceb0] <= QGuiApplicationPrivate::init[7f6ac6692f7b])
[0] (QGuiApplication::QGuiApplication[5597790210f8] <= main[5597790213f2])
mcount: /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:45:segv_handler
 ERROR: invalid memory access: 7f6ac58349a8: exiting.
mcount: shmem_finish: tid: 6169 seqnum = 3 curr = 1, nr_buf = 2 max_buf = 2
mcount: exit from libmcount
uftrace: reading uftrace.data/task.txt file
uftrace: flushing /uftrace-37708c16716fd16d-6169-000
uftrace: flushing /uftrace-37708c16716fd16d-6172-000
uftrace: flushing /uftrace-37708c16716fd16d-6169-001
uftrace: flushing /uftrace-37708c16716fd16d-6169-000
uftrace: flushing /uftrace-37708c16716fd16d-6169-001
symbol: error during open symbol file: libgail.so: No such file or directory
symbol: error during open symbol file: libgail.so: No such file or directory
symbol: error during open elf file: libgail.so: No such file or directory
symbol: error during open symbol file: libatk-bridge.so: No such file or directory
symbol: error during open symbol file: libatk-bridge.so: No such file or directory
symbol: error during open elf file: libatk-bridge.so: No such file or directory

It seems that the recent exception change makes this difference. If I go back to the version before the exception change, the error message is the same.

$ uftrace record --nest-libcall planets
QML debugging is enabled. Only use this in a safe environment.
Inconsistency detected by ld.so: ../elf/dl-runtime.c: 79: _dl_fixup: Assertion `ELFW(R_TYPE)(reloc->r_info) == ELF_MACHINE_JMP_SLOT' failed!

$ uftrace --version
uftrace v0.8.2-13-g01ca

[honggyukim]

Here is the gdb backtrace.

(gdb) bt
#0  0x00007ffff7bb7a52 in overwrite_pltgot (pd=0x555555cf8e80, data=<optimized out>, idx=2) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:59
#1  find_got (offset=93824992231424, nr_dyn=<optimized out>, dyn_data=<optimized out>, modname=0x7ffff7dd5ae0 <exename> "/home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/buil
d-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug/planets", elf=<optimized out>) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:269
#2  hook_pltgot (modname=modname@entry=0x7ffff7dd5ae0 <exename> "/home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug/planets", off
set=offset@entry=93824992231424) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:339
#3  0x00007ffff7bb7c5f in setup_mod_plthook_data (info=<optimized out>, sz=<optimized out>, arg=<optimized out>) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:530
#4  0x00007ffff587cd24 in dl_iterate_phdr () from /lib/x86_64-linux-gnu/libc.so.6
#5  0x00007ffff7bb70bc in mcount_setup_plthook (exename=0x7ffff7dd5ae0 <exename> "/home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-De
bug/planets", nest_libcall=<optimized out>) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:556
#6  0x00007ffff7bb2d43 in mcount_startup () at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/mcount.c:1212
#7  mcount_init () at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/mcount.c:1303
#8  0x00007ffff7de79ca in ?? () from /lib64/ld-linux-x86-64.so.2
#9  0x00007ffff7de7adb in ?? () from /lib64/ld-linux-x86-64.so.2
#10 0x00007ffff7dd7c5a in ?? () from /lib64/ld-linux-x86-64.so.2
#11 0x0000000000000001 in ?? ()
#12 0x00007fffffffdccb in ?? ()
#13 0x0000000000000000 in ?? ()

[honggyukim]

 49│ static void overwrite_pltgot(struct plthook_data *pd, int idx, void *data)
 50│ {
 51│         /* save got_addr for segv_handler */
 52│         got_addr = (unsigned long)(&pd->pltgot_ptr[idx]);
 53│
 54│         segv_handled = false;
 55│
 56│         compiler_barrier();
 57│
 58│         /* overwrite it - might be write-protected */
 59├───────> pd->pltgot_ptr[idx] = (unsigned long)data;
 60│
 61│         if (segv_handled)
 62│                 mprotect(PAGE_ADDR(got_addr), PAGE_SIZE, PROT_READ);
 63│ }
        ...
(gdb) p idx
$1 = 2
(gdb) p *pd
$2 = {
  list = {
    prev = 0x7ffff7dd5650 <plthook_modules>,
    next = 0x7ffff7dd5650 <plthook_modules>
  },
  mod_name = 0x555555cf8f00 "/home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug/planets",
  module_id = 0,
  base_addr = 93824992231424,
  plt_addr = 93824992235712,
  dsymtab = {
    sym = 0x555555cf9340,
    sym_names = 0x555555cf97b0,
    nr_sym = 29,
    nr_alloc = 32,
    name_sorted = false
  },
  pltgot_ptr = 0x555555cdaed0,
  resolved_addr = 0x555555cf98a0,
  special_funcs = 0x0,
  nr_special = 0
}

[namhyung]

Thanks, could you please show me the output of readelf -d planets?

[honggyukim]

Here's the readelf log.

$ readelf -d planets

Dynamic section at offset 0x586ca0 contains 31 entries:
  Tag        Type                         Name/Value
 0x0000000000000001 (NEEDED)             Shared library: [libQt5Quick.so.5]
 0x0000000000000001 (NEEDED)             Shared library: [libQt5Gui.so.5]
 0x0000000000000001 (NEEDED)             Shared library: [libQt5Qml.so.5]
 0x0000000000000001 (NEEDED)             Shared library: [libQt5Core.so.5]
 0x0000000000000001 (NEEDED)             Shared library: [libstdc++.so.6]
 0x0000000000000001 (NEEDED)             Shared library: [libgcc_s.so.1]
 0x0000000000000001 (NEEDED)             Shared library: [libc.so.6]
 0x000000000000001d (RUNPATH)            Library runpath: [/home/honggyu/work.hdd/Qt/5.9.1/gcc_64/lib]
 0x000000000000000c (INIT)               0x10a0
 0x000000000000000d (FINI)               0x1b74
 0x0000000000000019 (INIT_ARRAY)         0x786c78
 0x000000000000001b (INIT_ARRAYSZ)       24 (bytes)
 0x000000000000001a (FINI_ARRAY)         0x786c90
 0x000000000000001c (FINI_ARRAYSZ)       8 (bytes)
 0x000000006ffffef5 (GNU_HASH)           0x298
 0x0000000000000005 (STRTAB)             0x6c0
 0x0000000000000006 (SYMTAB)             0x2d0
 0x000000000000000a (STRSZ)              1200 (bytes)
 0x000000000000000b (SYMENT)             24 (bytes)
 0x0000000000000015 (DEBUG)              0x0
 0x0000000000000003 (PLTGOT)             0x786ed0
 0x0000000000000007 (RELA)               0xcc8
 0x0000000000000008 (RELASZ)             984 (bytes)
 0x0000000000000009 (RELAENT)            24 (bytes)
 0x000000000000001e (FLAGS)              BIND_NOW
 0x000000006ffffffb (FLAGS_1)            Flags: NOW PIE
 0x000000006ffffffe (VERNEED)            0xbc8
 0x000000006fffffff (VERNEEDNUM)         7
 0x000000006ffffff0 (VERSYM)             0xb70
 0x000000006ffffff9 (RELACOUNT)          5
 0x0000000000000000 (NULL)               0x0

[namhyung]

Hmm.. it seems to have no PLT at all. I'll think about the case..

[honggyukim]

Thanks! Here is objdump disassemble output as well.

planets:     file format elf64-x86-64

Disassembly of section .init:

00000000000010a0 <_init>:
    10a0:       48 83 ec 08             sub    $0x8,%rsp
    10a4:       48 8b 05 ed 5e 78 00    mov    0x785eed(%rip),%rax        # 786f98 <__gmon_start__>
    10ab:       48 85 c0                test   %rax,%rax
    10ae:       74 02                   je     10b2 <_init+0x12>
    10b0:       ff d0                   callq  *%rax
    10b2:       48 83 c4 08             add    $0x8,%rsp
    10b6:       c3                      retq

Disassembly of section .plt:

00000000000010c0 <.plt>:
    10c0:       ff 35 12 5e 78 00       pushq  0x785e12(%rip)        # 786ed8 <_GLOBAL_OFFSET_TABLE_+0x8>
    10c6:       ff 25 14 5e 78 00       jmpq   *0x785e14(%rip)        # 786ee0 <_GLOBAL_OFFSET_TABLE_+0x10>
    10cc:       0f 1f 40 00             nopl   0x0(%rax)

Disassembly of section .plt.got:

00000000000010d0 <.plt.got>:
    10d0:       ff 25 12 5e 78 00       jmpq   *0x785e12(%rip)        # 786ee8 <_ZN7QWindow4showEv@Qt_5>
    10d6:       66 90                   xchg   %ax,%ax
    10d8:       ff 25 12 5e 78 00       jmpq   *0x785e12(%rip)        # 786ef0 <_ZNK7QString8multiArgEiPPKS_@Qt_5>
    10de:       66 90                   xchg   %ax,%ax
    10e0:       ff 25 12 5e 78 00       jmpq   *0x785e12(%rip)        # 786ef8 <_ZN4QUrlD1Ev@Qt_5>
    10e6:       66 90                   xchg   %ax,%ax
    10e8:       ff 25 1a 5e 78 00       jmpq   *0x785e1a(%rip)        # 786f08 <__stack_chk_fail@GLIBC_2.4>
    10ee:       66 90                   xchg   %ax,%ax
    10f0:       ff 25 1a 5e 78 00       jmpq   *0x785e1a(%rip)        # 786f10 <_ZN10QQmlEngine13addImportPathERK7QString@Qt_5>
    10f6:       66 90                   xchg   %ax,%ax
        ...

[namhyung]

Does this patch make any difference?

diff --git a/libmcount/plthook.c b/libmcount/plthook.c
index cafd0e2..309e5d9 100644
--- a/libmcount/plthook.c
+++ b/libmcount/plthook.c
@@ -264,9 +264,9 @@ static int find_got(Elf *elf, const char *modname,
                        pd->pltgot_ptr, plthook_resolver_addr);

                restore_plt_functions(pd);
-       }

-       overwrite_pltgot(pd, 2, plt_hooker);
+               overwrite_pltgot(pd, 2, plt_hooker);
+       }

        if (bind_now) {
                mcount_arch_undo_bindnow(elf, pd);

[honggyukim]

Hmm.. a bit differen but not working as well.

$ uftrace record --nest-libcall -v planets
uftrace: removing uftrace.data.old directory
uftrace: skipping perf event due to error: Permission denied
uftrace: please check /proc/sys/kernel/perf_event_paranoid
uftrace: creating 2 thread(s) for recording
uftrace: using libmcount.so library for tracing
mcount: initializing mcount library
mcount: setup PLT hooking (nest-libcall)
mcount: mcount setup done
mcount: /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:45:segv_handler
 ERROR: invalid memory access: 7f40bd12e010: exiting.
mcount: shmem_finish: tid: 13552 seqnum = 0 curr = 0, nr_buf = 0 max_buf = 0
mcount: exit from libmcount
uftrace: child terminated with exit code: 1

$ cgdb --args uftrace record --nest-libcall planets
        ...
0x00007ffff7bb6eb4 in overwrite_pltgot (pd=0x555555cf8e80, data=0x7ffff7ff2000, idx=3) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:59
(gdb) p idx
$1 = 3
(gdb) p *pd
$2 = {
  list = {
    prev = 0x7ffff7dd5650 <plthook_modules>,
    next = 0x7ffff7dd5650 <plthook_modules>
  },
  mod_name = 0x555555cf8f00 "/home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug/planets",
  module_id = 0,
  base_addr = 93824992231424,
  plt_addr = 93824992235712,
  dsymtab = {
    sym = 0x555555cf9340,
    sym_names = 0x555555cf97b0,
    nr_sym = 29,
    nr_alloc = 32,
    name_sorted = false
  },
  pltgot_ptr = 0x555555cdaed0,
  resolved_addr = 0x555555cf98a0,
  special_funcs = 0x0,
  nr_special = 0
}

[namhyung]

The gdb backtrace again, please..

[honggyukim]

Sure.

(gdb) bt
#0  0x00007ffff7bb6eb4 in overwrite_pltgot (pd=0x555555cf8e80, data=0x7ffff7ff2000, idx=3) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:59
#1  setup_pltgot (pd=pd@entry=0x555555cf8e80, got_idx=got_idx@entry=3, sym_idx=sym_idx@entry=0, data=data@entry=0x7ffff7ff2000) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/p
lthook.c:72
#2  0x00007ffff7bc914d in mcount_arch_undo_bindnow (elf=<optimized out>, pd=0x555555cf8e80) at /home/honggyu/src/uftrace/git/clean/uftrace/arch/x86_64/mcount-support.c:247
#3  0x00007ffff7bb773d in find_got (offset=93824992231424, nr_dyn=<optimized out>, dyn_data=<optimized out>, modname=0x7ffff7dd5ae0 <exename> "/home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1
/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug/planets", elf=<optimized out>) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:272
#4  hook_pltgot (modname=modname@entry=0x7ffff7dd5ae0 <exename> "/home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-Debug/planets", off
set=offset@entry=93824992231424) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:339
#5  0x00007ffff7bb7c4f in setup_mod_plthook_data (info=<optimized out>, sz=<optimized out>, arg=<optimized out>) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:530
#6  0x00007ffff587cd24 in dl_iterate_phdr () from /lib/x86_64-linux-gnu/libc.so.6
#7  0x00007ffff7bb70bc in mcount_setup_plthook (exename=0x7ffff7dd5ae0 <exename> "/home/honggyu/work.hdd/Qt/Examples/Qt-5.9.1/canvas3d/threejs/build-planets-Desktop_Qt_5_9_1_GCC_64bit-De
bug/planets", nest_libcall=<optimized out>) at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/plthook.c:556
#8  0x00007ffff7bb2d43 in mcount_startup () at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/mcount.c:1212
#9  mcount_init () at /home/honggyu/src/uftrace/git/clean/uftrace/libmcount/mcount.c:1303
#10 0x00007ffff7de79ca in ?? () from /lib64/ld-linux-x86-64.so.2
#11 0x00007ffff7de7adb in ?? () from /lib64/ld-linux-x86-64.so.2
#12 0x00007ffff7dd7c5a in ?? () from /lib64/ld-linux-x86-64.so.2
#13 0x0000000000000001 in ?? ()
#14 0x00007fffffffdccb in ?? ()
#15 0x0000000000000000 in ?? ()

[namhyung]

Hmm.. could you please show readelf -r planets as well?

[honggyukim]

$ readelf -r planets

Relocation section '.rela.dyn' at offset 0xcc8 contains 41 entries:
  Offset          Info           Type           Sym. Value    Sym. Name + Addend
000000786c78  000000000008 R_X86_64_RELATIVE                    12c0
000000786c80  000000000008 R_X86_64_RELATIVE                    16af
000000786c88  000000000008 R_X86_64_RELATIVE                    1ade
000000786c90  000000000008 R_X86_64_RELATIVE                    1280
000000787008  000000000008 R_X86_64_RELATIVE                    787008
000000786ee8  000100000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN7QWindow4showEv@Qt_5 + 0
000000786ef0  000200000006 R_X86_64_GLOB_DAT 0000000000000000 _ZNK7QString8multiArgE@Qt_5 + 0
000000786ef8  000300000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN4QUrlD1Ev@Qt_5 + 0
000000786f00  000400000006 R_X86_64_GLOB_DAT 0000000000000000 qt_version_tag@Qt_5.9 + 0
000000786f08  000500000006 R_X86_64_GLOB_DAT 0000000000000000 __stack_chk_fail@GLIBC_2.4 + 0
000000786f10  000600000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN10QQmlEngine13addIm@Qt_5 + 0
000000786f18  000700000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN15QGuiApplicationC1@Qt_5 + 0
000000786f20  000800000006 R_X86_64_GLOB_DAT 0000000000000000 strlen@GLIBC_2.2.5 + 0
000000786f28  000900000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN10QArrayData10deall@Qt_5 + 0
000000786f30  000a00000006 R_X86_64_GLOB_DAT 0000000000000000 _Unwind_Resume@GCC_3.0 + 0
000000786f38  000b00000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN16QCoreApplication1@Qt_5 + 0
000000786f40  000c00000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN10QQuickViewC1EP7QW@Qt_5 + 0
000000786f48  000d00000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN10QQuickView13setRe@Qt_5 + 0
000000786f50  000e00000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN7QString17fromLatin@Qt_5 + 0
000000786f58  000f00000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN15QGuiApplicationD1@Qt_5 + 0
000000786f60  001000000006 R_X86_64_GLOB_DAT 0000000000000000 __cxa_atexit@GLIBC_2.2.5 + 0
000000786f68  001100000006 R_X86_64_GLOB_DAT 0000000000000000 _ITM_registerTMCloneTa + 0
000000786f70  001200000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN12QQuickWindow8setC@Qt_5 + 0
000000786f78  001300000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN10QQuickViewD1Ev@Qt_5 + 0
000000786f80  001400000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN15QGuiApplication4e@Qt_5 + 0
000000786f88  001500000006 R_X86_64_GLOB_DAT 0000000000000000 _ITM_deregisterTMClone + 0
000000786f90  001600000006 R_X86_64_GLOB_DAT 0000000000000000 __cxa_finalize@GLIBC_2.2.5 + 0
000000786f98  001700000006 R_X86_64_GLOB_DAT 0000000000000000 __gmon_start__ + 0
000000786fa0  001800000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN6QColorC1EN2Qt11Glo@Qt_5 + 0
000000786fa8  001900000006 R_X86_64_GLOB_DAT 0000000000000000 _ZNK10QQuickView6engin@Qt_5 + 0
000000786fb0  001b00000006 R_X86_64_GLOB_DAT 0000000000000000 _Jv_RegisterClasses + 0
000000786fb8  001c00000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN10QQuickView9setSou@Qt_5 + 0
000000786fc0  001d00000006 R_X86_64_GLOB_DAT 0000000000000000 _Z21qRegisterResourceD@Qt_5 + 0
000000786fc8  001e00000006 R_X86_64_GLOB_DAT 0000000000000000 _Z23qUnregisterResourc@Qt_5 + 0
000000786fd0  001f00000006 R_X86_64_GLOB_DAT 0000000000000000 _Z9qt_assertPKcS0_i@Qt_5 + 0
000000786fd8  002000000006 R_X86_64_GLOB_DAT 0000000000000000 __libc_start_main@GLIBC_2.2.5 + 0
000000786fe0  002100000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN4QUrlC1ERK7QStringN@Qt_5 + 0
000000786fe8  002200000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN7QWindow8setTitleER@Qt_5 + 0
000000786ff0  002300000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN7QString16fromAscii@Qt_5 + 0
000000786ff8  002400000006 R_X86_64_GLOB_DAT 0000000000000000 _ZN20QQmlDebuggingEnab@Qt_5 + 0
000000787010  001a00000001 R_X86_64_64       0000000000000000 __gxx_personality_v0@CXXABI_1.3 + 0

[namhyung]

Could you please check the review/plthook-fix-v1 branch?

[honggyukim]

Thanks but it shows assertion fail.

$ uftrace record --nest-libcall planets
planets: /home/honggyu/src/uftrace/git/uftrace/arch/x86_64/mcount-support.c:265: mcount_arch_undo_bindnow: Assertion `!strcmp(sym->name, name)' failed.
child terminated by signal: 6: Aborted

[namhyung]

Hmm.. it should be same. Maybe a demangler issue; does the following patch makes a difference?

diff --git a/libmcount/plthook.c b/libmcount/plthook.c
index 41b0dd6..34a97e4 100644
--- a/libmcount/plthook.c
+++ b/libmcount/plthook.c
@@ -206,7 +206,7 @@ static int find_got(Elf *elf, const char *modname,
                pd->mod_name, pd->module_id, pd->base_addr ,pd->pltgot_ptr);

        memset(&pd->dsymtab, 0, sizeof(pd->dsymtab));
-       load_elf_dynsymtab(&pd->dsymtab, elf, pd->base_addr, SYMTAB_FL_DEMANGLE);
+       load_elf_dynsymtab(&pd->dsymtab, elf, pd->base_addr, 0);

        pd->resolved_addr = xcalloc(pd->dsymtab.nr_sym, sizeof(long));
        pd->special_funcs = NULL;

[honggyukim]

Hmm.. With the patch avoid on top of review/plthook-fix-v1, uftrace shows the assertion again.

$ uftrace record --nest-libcall planets
QML debugging is enabled. Only use this in a safe environment.
Inconsistency detected by ld.so: ../elf/dl-runtime.c: 79: _dl_fixup: Assertion `ELFW(R_TYPE)(reloc->r_info) == ELF_MACHINE_JMP_SLOT' failed!

The message is the same as the version in master.

[honggyukim]

With the recent commit 587e3eb144b6bb15e608db72babd3c6a42a0c368, I got the different segfault as follows:

$ cgdb --args uftrace --nest-libcall --no-pager planets
    ...
(gdb) bt
#0  0x00007fffffffdc80 in ?? ()
#1  0x00005555555551c0 in ?? ()
#2  0x00007ffff7bc8109 in plt_hooker () at /home/honggyu/src/uftrace/git/uftrace/arch/x86_64/plthook.S:55
#3  0x00007fffffffdd68 in ?? ()
#4  0x0000000155cdac78 in ?? ()
#5  0x00007fffffffdd78 in ?? ()
#6  0x00007fffffffdd68 in ?? ()
#7  0x00007fffffffdc30 in ?? ()
#8  0x00007ffff7bc811e in plthook_return () at /home/honggyu/src/uftrace/git/uftrace/arch/x86_64/plthook.S:72
#9  0x0000555555d944c0 in ?? ()
#10 0x00007ffff7b9d080 in vtable for QQuickView () from /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/lib/libQt5Quick.so.5
#11 0x0000555555dde260 in ?? ()
#12 0x00007ffff7b9d1a8 in vtable for QQuickView () from /home/honggyu/work.hdd/Qt/5.9.1/gcc_64/lib/libQt5Quick.so.5
#13 0x0000555500000000 in ?? ()
#14 0x0000000000000000 in ?? ()

[namhyung]

I also saw a different error - but interestingly, skipping libQt5Gui.so during PLT hooking removed the problem. Could you please check review/plthook-fix-v2?

[honggyukim]

@namhyung Thanks but the error looks same even with plthook-fix-v2.

$ uftrace record --nest-libcall planets
QML debugging is enabled. Only use this in a safe environment.
Inconsistency detected by ld.so: ../elf/dl-runtime.c: 79: _dl_fixup: Assertion `ELFW(R_TYPE)(reloc->r_info) == ELF_MACHINE_JMP_SLOT' failed!

[honggyukim]

There's another test program.

$ uftrace record --nest-libcall ./qml hello.qml
Segmentation fault: address not mapped (addr: 0x396)
child terminated by signal: 11: Segmentation fault

review/plthook-fix-v2 fixes the problem in a simple qml execution although it doesn't fix platnet example.

$ uftrace record --nest-libcall ./qml hello.qml

$ uftrace info
# system information
# ==================
# program version     : uftrace v0.8.2-74-g01de
# recorded on         : Wed Jan  3 17:31:28 2018
# cmdline             : uftrace record --nest-libcall ./qml hello.qml
# cpu info            : Intel(R) Core(TM) i7-4790K CPU @ 4.00GHz
# number of cpus      : 8 / 8 (online / possible)
# memory info         : 2.4 / 15.5 GB (free / total)
# system load         : 0.58 / 0.63 / 0.32 (1 / 5 / 15 min)
# kernel version      : Linux 4.10.0-42-generic
# hostname            : kvt
# distro              : "Ubuntu 17.04"
#
# process information
# ===================
# number of tasks     : 5
# task list           : 10544(qml), 10547(qml), 10548(qml), 10549(qml), 10550(qml)
# exe image           : /home/honggyu/src/qt/git/qt5/qtbase/bin/qml
# build id            : 09887942e683b640f36e91aa27e89dfec862d003
# exit status         : unknown exit status: -1
# elapsed time        : 1.454481399 sec
# cpu time            : 0.000 / 0.000 sec (sys / user)
# context switch      : 0 / 0 (voluntary / involuntary)
# max rss             : 0 KB
# page fault          : 0 / 0 (major / minor)
# disk iops           : 0 / 0 (read / write)

[namhyung]

Hmm.. ok. Could you please check review/plthook-v3 still fixes the simple case?

[honggyukim]

Sorry but I may have to test it after a while due to some environmental issues. Thanks very much for the update anyway.