Some boost based unit tests failing on Fedora 30 when linked with boost from host - 1.69.0

[Waldek Kozaczuk]

I have been trying to upgrade unit tests to use boost from host instead of depending on externals. One one the previous patches I sent fixed compilation errors.

However when I update the tests makefile and manifest file I see that some tests fail with very similar page fault error on Fedora 30 which comes with boost 1.69.0. The same tests pass just fine on latest Ubuntu 19.10 hat comes with older boost 1.67.0. 

Here is the patch:

diff --git a/modules/tests/Makefile b/modules/tests/Makefile

index e4ef8dcc..a5633308 100644

--- a/modules/tests/Makefile

+++ b/modules/tests/Makefile

@@ -177,12 +177,9 @@ zfs-only-boost-tests := tst-rename.so

 

 boost-tests += $($(fs_type)-only-boost-tests)

 

-BOOSTLIBS=$(src)/external/$(ARCH)/misc.bin/usr/lib64

 $(boost-tests:%=$(out)/tests/%): LIBS += \

-        $(BOOSTLIBS)/libboost_unit_test_framework.so \

-        $(BOOSTLIBS)/libboost_filesystem.so

-$(boost-tests:%=$(out)/tests/%): CXXFLAGS += -D_GLIBCXX_USE_CXX11_ABI=0 \

-       -isystem $(src)/external/$(ARCH)/misc.bin/usr/include

+        -lboost_unit_test_framework \

+        -lboost_filesystem

 

 tests += $(boost-tests)

 

diff --git a/modules/tests/usr.manifest.skel b/modules/tests/usr.manifest.skel

index 2de441f9..7653760a 100644

--- a/modules/tests/usr.manifest.skel

+++ b/modules/tests/usr.manifest.skel

@@ -1,4 +1,4 @@

-/usr/lib/&/libboost_unit_test_framework.so.1.55.0: %(miscbase)s/usr/lib64/&

-/usr/lib/&/libboost_filesystem.so.1.55.0: %(miscbase)s/usr/lib64/&

-/usr/lib/&/libboost_system.so.1.55.0: %(miscbase)s/usr/lib64/&

+/usr/lib/&/libboost_unit_test_framework.so.1.69.0: /lib64/&

+/usr/lib/&/libboost_filesystem.so.1.69.0: /lib64/&

+/usr/lib/&/libboost_system.so.1.69.0: /lib64/&

 /testrunner.so: ./tests/testrunner.so

The error looks similar and affects tst-rcu-hashtable, tst-rcu-list and tst-rename. There may be more tests after tst-rename that fail like that:

  TEST tst-rcu-hashtable.so               Running OSv on qemu with parameters: [-s -e --power-off-on-abort /tests/tst-rcu-hashtable.so --pass-args=-monitor unix:qemu-monitor,server,nowait --block-device-cache unsafe]

OSv v0.54.0-44-g5526c8ab

eth0: 192.168.122.15

Booted up in 186.88 ms

Cmdline: /tests/tst-rcu-hashtable.so

Running 2 test cases...

*** No errors detected

Aborted

[backtrace]

0x00000000402197c3 <???+1075943363>

0x0000000040463f7e <osv::handle_mmap_fault(unsigned long, int, exception_frame*)+30>

0x000000004033da01 <mmu::vm_fault(unsigned long, exception_frame*)+385>

0x000000004039d62f <page_fault+143>

0x000000004039c486 <???+1077527686>

0x000010000041f5f6 <???+4322806>

0x0000000040352c5c <elf::object::run_fini_funcs()+140>

0x0000000040354616 <elf::program::remove_object(elf::object*)+118>

0x0000000040354e30 <???+1077235248>

0x0000000040354ae4 <elf::program::remove_object(elf::object*)+1348>

0x0000000040354e30 <???+1077235248>

0x000000004042c14f <osv::application::join()+623>

0x000000004022a504 <do_main_thread(void*)+2644>

0x000000004045fdb5 <???+1078328757>

0x00000000403f9ce7 <thread_main_c+39>

0x000000004039d402 <???+1077531650>

Test tst-rcu-hashtable.so FAILED

Traceback (most recent call last):

  File "./scripts/test.py", line 204, in <module>

    main()

  File "./scripts/test.py", line 183, in main

    run_tests()

  File "./scripts/test.py", line 174, in run_tests

    run(tests_to_run)

  File "./scripts/test.py", line 94, in run

    run_test(test)

  File "./scripts/test.py", line 69, in run_test

    test.run()

  File "/git-repos/osv/scripts/tests/testing.py", line 38, in run

    run_command_in_guest(self.command, hypervisor=self.hypervisor, run_py_args=self.run_py_args).join()

  File "/git-repos/osv/scripts/tests/testing.py", line 186, in join

    raise Exception('Guest failed')

Exception: Guest failed

Somewhat broken  gdb stacktrace looks like this:

(gdb) bt

#0  0x00000000403a36f2 in processor::cli_hlt () at arch/x64/processor.hh:247

#1  arch::halt_no_interrupts () at arch/x64/arch.hh:48

#2  osv::halt () at arch/x64/power.cc:26

#3  0x0000000040239d4e in abort (fmt=fmt@entry=0x406414bf "Aborted\n")

    at runtime.cc:132

#4  0x00000000402028ab in abort () at runtime.cc:98

#5  0x00000000402197c4 in osv::generate_signal (siginfo=..., 

    ef=0xffff80000123c068) at libc/signal.cc:124

#6  0x0000000040463f7f in osv::handle_mmap_fault (addr=<optimized out>, 

    sig=<optimized out>, ef=<optimized out>) at libc/signal.cc:139

#7  0x000000004033da02 in mmu::vm_fault (addr=17592187015168, 

    addr@entry=17592187015648, ef=ef@entry=0xffff80000123c068)

    at core/mmu.cc:1337

#8  0x000000004039d630 in page_fault (ef=0xffff80000123c068)

    at arch/x64/mmu.cc:42

#9  <signal handler called>

#10 0x00001000000ed1e0 in ?? ()

#11 0x000000004023a2f7 in __cxxabiv1::__cxa_finalize (dso=<optimized out>)

    at runtime.cc:183

#12 0x000010000041f5f7 in ?? ()

#13 0x0000200000100940 in ?? ()

#14 0x0000000040352c5d in elf::object::run_fini_funcs (this=0xffffa0000160ee00)

    at core/elf.cc:1070

It happens consistently. Any idea what might be wrong?

Waldek

[Nadav Har'El]

On Thu, Nov 28, 2019 at 8:00 AM Waldek Kozaczuk <jwkoz...@gmail.com> wrote:

I have been trying to upgrade unit tests to use boost from host instead of depending on externals. One one the previous patches I sent fixed compilation errors.

However when I update the tests makefile and manifest file I see that some tests fail with very similar page fault error on Fedora 30 which comes with boost 1.69.0. The same tests pass just fine on latest Ubuntu 19.10 hat comes with older boost 1.67.0.

Just to make sure, please make sure to delete the old compilation results ("make clean") so we don't see some mixture of old and new stuff.

I'm assuming this patch is only temporary - in the final version, please don't use these specific version names in the usr.manifest.skel - it will only work in your setup - we need to figure this out automatically with ldd.

Is the backtrace broken? The important line is

#10 0x00001000000ed1e0 in ?? ()

Which is inside the test executable. Did you try "osv syms"?

It seems there is a C++ destructor in the test code (or Boost framework) being run, which causes a crash. But I don't know what it is...

 

--
You received this message because you are subscribed to the Google Groups "OSv Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to osv-dev+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/osv-dev/5539bd38-a7d8-485f-ba51-40b90c16d0f5%40googlegroups.com.

[Waldek Kozaczuk]

On Thursday, November 28, 2019 at 3:08:53 AM UTC-5, Nadav Har'El wrote:

On Thu, Nov 28, 2019 at 8:00 AM Waldek Kozaczuk <jwkoz...@gmail.com> wrote:

I have been trying to upgrade unit tests to use boost from host instead of depending on externals. One one the previous patches I sent fixed compilation errors.

However when I update the tests makefile and manifest file I see that some tests fail with very similar page fault error on Fedora 30 which comes with boost 1.69.0. The same tests pass just fine on latest Ubuntu 19.10 hat comes with older boost 1.67.0.

Just to make sure, please make sure to delete the old compilation results ("make clean") so we don't see some mixture of old and new stuff.

Did not help. 

Please note I have removed this line from the tests Makefile:

-$(boost-tests:%=$(out)/tests/%): CXXFLAGS += -D_GLIBCXX_USE_CXX11_ABI=0 \

I do not fully understand the significance of it nor the reasons for it in the first place (why was it there). Could it cause this issue?

With this line the boost based tests would fail like so:

/tests/tst-async.so: failed looking up symbol _ZN5boost9unit_test9ut_detail24normalize_test_case_nameENS0_13basic_cstringIKcEE (boost::unit_test::ut_detail::normalize_test_case_name(boost::unit_test::basic_cstring<char const>))

[backtrace]

0x00000000403558c6 <elf::object::symbol(unsigned int, bool)+1542>

0x0000000040355992 <elf::object::resolve_pltgot(unsigned int)+130>

0x0000000040355c93 <elf_resolve_pltgot+51>

0x000000004039c0bd <???+1077526717>

0x0000200000200e0f <???+2100751>

0x010000100000080e <???+2062>

BTW I also now noticed this linker warning (not sure if related):

  LIBOSV.SO

  STRIP loader.elf -> loader-stripped.elf 

strip: build/release.x64/loader.elf[.gnu.build.attributes.text._ZN5boost6system23dummy_exported_functionEv]: Warning: version note missing - assuming version 3

strip:build/release.x64/loader-stripped.elf[.gnu.build.attributes.unlikely]: error: failed to copy merged notes into output: file in wrong format

  LZ loader-stripped.elf

I did. There were couple of libraries that had missing debug info missing. Installed still did not help and backtrace looks like this - broken: 

It seems there is a C++ destructor in the test code (or Boost framework) being run, which causes a crash. But I don't know what it is...

Not sure it is related but our usr.manifest.skel pulls ancient libgc_s.so from externals. Changing it to pull from host creates other issues which I will send email about.  

 

To unsubscribe from this group and stop receiving emails from it, send an email to osv...@googlegroups.com.

[Nadav Har'El]

On Thu, Nov 28, 2019 at 10:04 PM Waldek Kozaczuk <jwkoz...@gmail.com> wrote:

 

Please note I have removed this line from the tests Makefile:

-$(boost-tests:%=$(out)/tests/%): CXXFLAGS += -D_GLIBCXX_USE_CXX11_ABI=0 \

I do not fully understand the significance of it nor the reasons for it in the first place (why was it there). Could it cause this issue?

This line was needed because we try to combine newly combined test code and some super-antique version of Boost from external/.

It is explained in commit 6a3bff38a281e65ee715bab4fadef63e0918f7d3. You shouldn't need it if you stop using the antique boost.

 

BTW I also now noticed this linker warning (not sure if related):

  LIBOSV.SO

  STRIP loader.elf -> loader-stripped.elf 

strip: build/release.x64/loader.elf[.gnu.build.attributes.text._ZN5boost6system23dummy_exported_functionEv]: Warning: version note missing - assuming version 3

strip:build/release.x64/loader-stripped.elf[.gnu.build.attributes.unlikely]: error: failed to copy merged notes into output: file in wrong format

  LZ loader-stripped.elf

I noticed this too a few days ago, but didn't spend any time to chase it.

 

 

Is the backtrace broken? The important line is

#10 0x00001000000ed1e0 in ?? ()

Which is inside the test executable. Did you try "osv syms"?

I did. There were couple of libraries that had missing debug info missing. Installed still did not help and backtrace looks like this - broken: 

I'm still guessing the address 0x00001000000ed1e0 is in the actual test itself, not any of the libraries.

It is possible that "osv syms" gets confused because this bug happens while the test executable is being unloaded, so maybe it's no longer in the list. You can comment out the code that removes the library from the list that "osv syms" uses, and then maybe gdb will be able to know about it.

 

It seems there is a C++ destructor in the test code (or Boost framework) being run, which causes a crash. But I don't know what it is...

Not sure it is related but our usr.manifest.skel pulls ancient libgc_s.so from externals.

The reason why we have this file is explained in commit be565320c082c00069614c850d29b42831b3dea6

 

Changing it to pull from host creates other issues which I will send email about.  

:-(

[Waldek Kozaczuk]

I think I have solved the mystery. It looks like another bug in the dynamic linker. This time related to an order in which objects are unloaded and FINI* functions are executed. And it just happens to be with the boost based unit tests that depend on more libraries with 1.69 version of boost.

And some boost tests pass just fine like this one:

Cmdline: /tests/tst-bsd-tcp1.so

ELF [tid:27, /libvdso.so]: Instantiated

ELF [tid:27, /libvdso.so]: The base set to: 0x0000000000063000 and end: 0x0000000000067030

ELF [tid:27, /libvdso.so]: Loading segments

ELF [tid:27, /libvdso.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000063000 of size: 0x1000

ELF [tid:27, /libvdso.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000064000 of size: 0x1000

ELF [tid:27, /libvdso.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000065000 of size: 0x1000

ELF [tid:27, /libvdso.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000066000 of size: 0x2000

ELF [tid:27, /libvdso.so]: Relocated 3 PLT symbols in DT_JMPREL

ELF [tid:27, /libvdso.so]: versioned symbol table

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Instantiated

ELF [tid:27, /tests/tst-bsd-tcp1.so]: The base set to: 0x0000000000068000 and end: 0x0000000000091630

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loading segments

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000068000 of size: 0x11000

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000079000 of size: 0x11000

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loaded and mapped PT_LOAD segment at: 0x000000000008a000 of size: 0x5000

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loaded and mapped PT_LOAD segment at: 0x000000000008f000 of size: 0x3000

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Found TLS segment at 0x000000000008f6a8 of aligned size: 8

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loading DT_NEEDED object: libboost_unit_test_framework.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: The base set to: 0x0000000000092000 and end: 0x000000000013f768

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000092000 of size: 0x1b000

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x00000000000ad000 of size: 0x6c000

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000119000 of size: 0x1f000

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000138000 of size: 0x6000

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libboost_timer.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: The base set to: 0x0000000000140000 and end: 0x00000000001490f0

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000140000 of size: 0x3000

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000143000 of size: 0x3000

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000146000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000148000 of size: 0x2000

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libboost_chrono.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: The base set to: 0x000000000014a000 and end: 0x0000000000158070

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000014a000 of size: 0x5000

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000014f000 of size: 0x5000

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000154000 of size: 0x2000

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000157000 of size: 0x2000

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libboost_system.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: The base set to: 0x0000000000159000 and end: 0x000000000015d008

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000159000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000015a000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000015b000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000015c000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Relocated 7 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Relocated 1 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libpthread.so.0 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Instantiated

ELF [tid:27, /usr/lib/libgcc_s.so.1]: The base set to: 0x0000000000200000 and end: 0x0000000000415400

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Loading segments

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Loaded and mapped PT_LOAD segment at: 0x0000000000200000 of size: 0x15000

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Loaded and mapped PT_LOAD segment at: 0x0000000000414000 of size: 0x2000

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Relocated 11 symbols in DT_RELA

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Relocated 44 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libgcc_s.so.1]: versioned symbol table

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Relocated 146 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Relocated 46 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: versioned symbol table

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libboost_system.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Relocated 70 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Relocated 51 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: versioned symbol table

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libboost_system.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libm.so.6 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libm.so.6 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libpthread.so.0 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Relocated 1622 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Relocated 293 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: versioned symbol table

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loading DT_NEEDED object: libboost_filesystem.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: The base set to: 0x0000000000416000 and end: 0x00000000004321c0

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000416000 of size: 0x7000

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000041d000 of size: 0xe000

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000042b000 of size: 0x5000

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000431000 of size: 0x2000

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libboost_system.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libpthread.so.0 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Relocated 133 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Relocated 139 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: versioned symbol table

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loading DT_NEEDED object: libm.so.6 

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Loading DT_NEEDED object: ld-linux-x86-64.so.2 

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Relocated 585 symbols in DT_RELA

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Relocated 143 PLT symbols in DT_JMPREL

ELF [tid:27, /tests/tst-bsd-tcp1.so]: versioned symbol table

ELF [tid:199, /usr/lib/libboost_filesystem.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_filesystem.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_filesystem.so.1.69.0]: Executing 3 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_filesystem.so.1.69.0]: Finished executing 3 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libgcc_s.so.1]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libgcc_s.so.1]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libgcc_s.so.1]: Executing 2 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libgcc_s.so.1]: Finished executing 2 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_system.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_system.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_system.so.1.69.0]: Executing 1 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_system.so.1.69.0]: Finished executing 1 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_chrono.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_chrono.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_chrono.so.1.69.0]: Executing 1 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_chrono.so.1.69.0]: Finished executing 1 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_timer.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_timer.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_timer.so.1.69.0]: Executing 3 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_timer.so.1.69.0]: Finished executing 3 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Executing 19 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Finished executing 19 DT_INIT_ARRAYSZ functions

ELF [tid:199, /tests/tst-bsd-tcp1.so]: Executing DT_INIT function

ELF [tid:199, /tests/tst-bsd-tcp1.so]: Finished executing DT_INIT function

ELF [tid:199, /tests/tst-bsd-tcp1.so]: Executing 2 DT_INIT_ARRAYSZ functions

ELF [tid:199, /tests/tst-bsd-tcp1.so]: Finished executing 2 DT_INIT_ARRAYSZ functions

Running 2 test cases...

ESC[1;32;49m*** No errors detected

ESC[0;39;49mELF [tid:27, /tests/tst-bsd-tcp1.so]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /tests/tst-bsd-tcp1.so]: Executing DT_FINI function

ELF [tid:27, /tests/tst-bsd-tcp1.so]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libgcc_s.so.1]: unloading object dependent objects 

ELF [tid:27, /libvdso.so]: unloading object dependent objects 

And here is the that fails:

Cmdline: /tests/tst-rcu-hashtable.so

ELF [tid:27, /libvdso.so]: Instantiated

ELF [tid:27, /libvdso.so]: The base set to: 0x0000000000063000 and end: 0x0000000000067030

ELF [tid:27, /libvdso.so]: Loading segments

ELF [tid:27, /libvdso.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000063000 of size: 0x1000

ELF [tid:27, /libvdso.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000064000 of size: 0x1000

ELF [tid:27, /libvdso.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000065000 of size: 0x1000

ELF [tid:27, /libvdso.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000066000 of size: 0x2000

ELF [tid:27, /libvdso.so]: Relocated 3 PLT symbols in DT_JMPREL

ELF [tid:27, /libvdso.so]: versioned symbol table

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Instantiated

ELF [tid:27, /tests/tst-rcu-hashtable.so]: The base set to: 0x0000000000068000 and end: 0x0000000000087400

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loading segments

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000068000 of size: 0xa000

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000072000 of size: 0xf000

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000081000 of size: 0x4000

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loaded and mapped PT_LOAD segment at: 0x0000000000086000 of size: 0x2000

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loading DT_NEEDED object: libboost_unit_test_framework.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: The base set to: 0x0000000000088000 and end: 0x0000000000135768

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000088000 of size: 0x1b000

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x00000000000a3000 of size: 0x6c000

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000010f000 of size: 0x1f000

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000012e000 of size: 0x6000

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libboost_timer.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: The base set to: 0x0000000000136000 and end: 0x000000000013f0f0

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000136000 of size: 0x3000

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000139000 of size: 0x3000

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000013c000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000013e000 of size: 0x2000

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libboost_chrono.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: The base set to: 0x0000000000140000 and end: 0x000000000014e070

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000140000 of size: 0x5000

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000145000 of size: 0x5000

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000014a000 of size: 0x2000

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000014d000 of size: 0x2000

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libboost_system.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: The base set to: 0x000000000014f000 and end: 0x0000000000153008

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000014f000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000150000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000151000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000152000 of size: 0x1000

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Relocated 7 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_system.so.1.69.0]: Relocated 1 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libpthread.so.0 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Instantiated

ELF [tid:27, /usr/lib/libgcc_s.so.1]: The base set to: 0x0000000000200000 and end: 0x0000000000415400

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Loading segments

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Loaded and mapped PT_LOAD segment at: 0x0000000000200000 of size: 0x15000

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Loaded and mapped PT_LOAD segment at: 0x0000000000414000 of size: 0x2000

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Relocated 11 symbols in DT_RELA

ELF [tid:27, /usr/lib/libgcc_s.so.1]: Relocated 44 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libgcc_s.so.1]: versioned symbol table

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Relocated 146 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Relocated 46 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: versioned symbol table

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libboost_system.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Relocated 70 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Relocated 51 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: versioned symbol table

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libboost_system.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libm.so.6 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libpthread.so.0 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Relocated 1622 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Relocated 293 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: versioned symbol table

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loading DT_NEEDED object: libboost_filesystem.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Instantiated

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: The base set to: 0x0000000000416000 and end: 0x00000000004321c0

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading segments

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000416000 of size: 0x7000

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000041d000 of size: 0xe000

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x000000000042b000 of size: 0x5000

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loaded and mapped PT_LOAD segment at: 0x0000000000431000 of size: 0x2000

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libboost_system.so.1.69.0 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: librt.so.1 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libpthread.so.0 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Relocated 133 symbols in DT_RELA

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Relocated 139 PLT symbols in DT_JMPREL

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: versioned symbol table

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loading DT_NEEDED object: libstdc++.so.6 

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loading DT_NEEDED object: libm.so.6 

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loading DT_NEEDED object: libgcc_s.so.1 

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Loading DT_NEEDED object: libc.so.6 

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Relocated 290 symbols in DT_RELA

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Relocated 111 PLT symbols in DT_JMPREL

ELF [tid:27, /tests/tst-rcu-hashtable.so]: versioned symbol table

ELF [tid:199, /usr/lib/libboost_filesystem.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_filesystem.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_filesystem.so.1.69.0]: Executing 3 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_filesystem.so.1.69.0]: Finished executing 3 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libgcc_s.so.1]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libgcc_s.so.1]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libgcc_s.so.1]: Executing 2 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libgcc_s.so.1]: Finished executing 2 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_system.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_system.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_system.so.1.69.0]: Executing 1 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_system.so.1.69.0]: Finished executing 1 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_chrono.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_chrono.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_chrono.so.1.69.0]: Executing 1 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_chrono.so.1.69.0]: Finished executing 1 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_timer.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_timer.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_timer.so.1.69.0]: Executing 3 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_timer.so.1.69.0]: Finished executing 3 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Finished executing DT_INIT function

ELF [tid:199, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Executing 19 DT_INIT_ARRAYSZ functions

ELF [tid:199, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Finished executing 19 DT_INIT_ARRAYSZ functions

ELF [tid:199, /tests/tst-rcu-hashtable.so]: Executing DT_INIT function

ELF [tid:199, /tests/tst-rcu-hashtable.so]: Finished executing DT_INIT function

ELF [tid:199, /tests/tst-rcu-hashtable.so]: Executing 2 DT_INIT_ARRAYSZ functions

ELF [tid:199, /tests/tst-rcu-hashtable.so]: Finished executing 2 DT_INIT_ARRAYSZ functions

Running 2 test cases...

*** No errors detected

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /tests/tst-rcu-hashtable.so]: Executing DT_FINI function

ELF [tid:27, /tests/tst-rcu-hashtable.so]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libboost_unit_test_framework.so.1.69.0]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libboost_timer.so.1.69.0]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Finished executing 1 DT_FINI_ARRAYSZ functions

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: Executing DT_FINI function

ELF [tid:27, /usr/lib/libboost_chrono.so.1.69.0]: unloading object dependent objects 

ELF [tid:27, /usr/lib/libboost_filesystem.so.1.69.0]: Executing 1 DT_FINI_ARRAYSZ functions

Aborted

[backtrace]

0x000000004021981d <???+1075943453>

0x0000000040463f7e <osv::handle_mmap_fault(unsigned long, int, exception_frame*)+30>

0x000000004033da61 <mmu::vm_fault(unsigned long, exception_frame*)+385>

0x000000004039dc2f <page_fault+143>

0x000000004039ca86 <???+1077529222>

0x000010000041f5f6 <???+4322806>

0x0000000040352f33 <elf::object::run_fini_funcs()+211>

0x0000000040354ab6 <elf::program::remove_object(elf::object*)+118>

0x00000000403551f0 <???+1077236208>

0x0000000040350cc4 <elf::object::unload_needed()+164>

0x0000000040354f14 <elf::program::remove_object(elf::object*)+1236>

0x00000000403551f0 <???+1077236208>

0x000000004042c14f <osv::application::join()+623>

0x000000004022a564 <do_main_thread(void*)+2644>

0x000000004045fdb5 <???+1078328757>

0x00000000403f9ce7 <thread_main_c+39>

0x000000004039da02 <???+1077533186>

As you can tell in the last test boost_filesystem, FINI function got executed after the libboost_unit_test_framework FINI function got called and unloaded. If you look at the first one, the order is opposite and that why it works.

I think we need to change unloading logic to first execute all FINI functions of all objects probably on the same thread that the INIT ones got executed and only then unload the objects.

What do you think?

[Nadav Har'El]

On Sat, Nov 30, 2019 at 5:32 AM Waldek Kozaczuk <jwkoz...@gmail.com> wrote:

I think I have solved the mystery. It looks like another bug in the dynamic linker. This time related to an order in which objects are unloaded and FINI* functions are executed.

I'm afraid I didn't quite follow the details below and what's wrong with the "wrong" order or what caused it.

I wonder if it's related to to issue https://github.com/cloudius-systems/osv/issues/334 but I don't know how.

 

As you can tell in the last test boost_filesystem, FINI function got executed after the libboost_unit_test_framework FINI function got called and unloaded. If you look at the first one, the order is opposite and that why it works.

Why is this order wrong?

If I understand correctly, our test loads (DT_NEED) libboost_unit_test_framework and that loads boost_filesystem

So you'd expect the program::remove_object() code to first finalize unit_test_framework, and only then unload its dependency (boost_filesystem).

So it sounds the order you call wrong, is right, no? If it's not right - then at least it was as intended ;-) And if this intent is wrong, it should be fixed (in remove_object())

But there is a complication: in modules/tests/Makefile I see our test depends on boost_filesystem *directly*.

So now the order that boost_filesystem gets unloaded may become random (because we analyze the entire DAG for dependencies....).

This may explain why in some cases we got the "opposite" order and everything worked.

 

I think we need to change unloading logic to first execute all FINI functions of all objects probably on the same thread that the INIT ones got executed and only then unload the objects.

This is an interesting point. Indeed the loading code first loads all the necessary objects in multiple levels, and only then runs all the init functions (in some hopefully correct object), the unloading code doesn't do this. But I don't think there's an easy way to do this, if at all.... It's not always true that objects get unloaded in one large batch. It can also happen like I mentioned above in our own example - boost_test_framework says it wants to unload boost_filesystem, BUT, it is not the last holder of boost_filesystem because the application also dt_needed boost_filesystem directly. So we can't unload boost_filesystem just yet... And need to delay its unload.

 

--

You received this message because you are subscribed to the Google Groups "OSv Development" group.

To unsubscribe from this group and stop receiving emails from it, send an email to osv-dev+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/osv-dev/861da7d5-7a27-4a0a-bb03-2d417c425e4b%40googlegroups.com.

[Waldek Kozaczuk]

Here is a little bit better-improved stacktrace after I used osv load_elf t manually load unit_test object:

osv load-elf /lib64/libboost_unit_test_framework.so.1.69.0 0x0000000000088000

(gdb) bt

#0  0x00000000403a3cf2 in processor::cli_hlt () at arch/x64/processor.hh:247

#1  arch::halt_no_interrupts () at arch/x64/arch.hh:48

#2  osv::halt () at arch/x64/power.cc:26

#3  0x0000000040239dae in abort (fmt=fmt@entry=0x4064155f "Aborted\n") at runtime.cc:132

#4  0x00000000402028ab in abort () at runtime.cc:98

#5  0x000000004021981e in osv::generate_signal (siginfo=..., ef=0xffff80000123c068) at libc/signal.cc:124

#6  0x0000000040463f7f in osv::handle_mmap_fault (addr=<optimized out>, sig=<optimized out>, ef=<optimized out>) at libc/signal.cc:139

#7  0x000000004033da62 in mmu::vm_fault (addr=17592187015168, addr@entry=17592187015648, ef=ef@entry=0xffff80000123c068) at core/mmu.cc:1337

#8  0x000000004039dc30 in page_fault (ef=0xffff80000123c068) at arch/x64/mmu.cc:42

#9  <signal handler called>

#10 0x00001000000ed1e0 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() ()

#11 0x000000004023a357 in __cxxabiv1::__cxa_finalize (dso=<optimized out>) at runtime.cc:183

#12 0x000010000041f5f7 in __do_global_dtors_aux ()

#13 0x00002000001008f0 in ?? ()

#14 0x0000000040352f34 in elf::object::run_fini_funcs (this=0xffffa000015d0a00) at core/elf.cc:1105

Backtrace stopped: frame did not save the PC

It looks like it crashes when trying to call the destructor of a string object.

Also here is what ELF spec (https://refspecs.linuxfoundation.org/elf/elf.pdf) says about calling termination functions (FINI*) in the "Initialization and Termination Functions" section:

"Similarly, shared objects may have termination functions, which are executed with the atexit(BA_OS) mechanism after the base process begins its termination sequence. The order in which the dynamic linker calls termination functions is the exact reverse order of their corresponding initialization functions. If a shared object has a termination function, but no initialization function, the termination function will execute in the order it would have as if the shared object's initialization function was present. The dynamic linker ensures that it will not execute any initialization or termination functions more than once."

Clearly our linker does not behave like this. Obviously I do not have 100% proof that the incorrect order in which dynamic linker executes termination functions leads to the crash we are seeing. But based on the printouts from another test that succeeds it seems likely to be a culprit.

To unsubscribe from this group and stop receiving emails from it, send an email to osv...@googlegroups.com.

[Waldek Kozaczuk]

The problem is that order in which objects are unloaded (calling program::remove_object()) is completely non-deterministic and based on where the last reference through shared_ptr is removed and remove_object() called.

We could save the order in which init functions are called by pushing objects removed in init_library() on another stack to capture the reversed object. But when would we act on it?

[Waldek Kozaczuk]

The other test tst-rename.so passes most of the time but sometimes fails with similar stack trace. 

I wonder if this code is deterministic:

void object::unload_needed()

{

    _needed.clear();

    _used_by_resolve_plt_got.clear();

}

The _needed is a vector but _used_by_resolve_plt_got is an unordered set.

[Waldek Kozaczuk]

So this WIP patch seems to make all tests pass including the boost ones that used to fail:

diff --git a/include/osv/elf.hh b/include/osv/elf.hh

index 9a0415dc..ea597c08 100644

--- a/include/osv/elf.hh

+++ b/include/osv/elf.hh

@@ -425,6 +425,7 @@ protected:

     std::unique_ptr<char[]> _section_names_cache;

     bool _is_executable;

     bool is_core();

+    bool _finalized = false;

 

     std::unordered_map<std::string,void*> _cached_symbols;

 

@@ -434,6 +435,7 @@ protected:

     std::vector<std::shared_ptr<elf::object>> _needed;

     std::unordered_set<std::shared_ptr<elf::object>> _used_by_resolve_plt_got;

     mutex _used_by_resolve_plt_got_mutex;

+    std::vector<elf::object*> _fini_objects;

     // Allow objects on program->_modules to be usable for the threads

     // currently initializing them, but not yet visible for other threads.

     // This simplifies the code (the initializer can use the regular lookup

@@ -457,6 +459,7 @@ private:

     bool visible(void) const;

 public:

     void setprivate(bool);

+    void add_fini_object(elf::object *_obj) { _fini_objects.push_back(_obj); }

 };

 

 class file : public object {

diff --git a/core/elf.cc b/core/elf.cc

index 909559a2..e4184e58 100644

--- a/core/elf.cc

+++ b/core/elf.cc

@@ -1096,6 +1096,9 @@ void object::run_init_funcs(int argc, char** argv)

 // Run the object's static destructors or similar finalization

 void object::run_fini_funcs()

 {

+    if (_finalized) {

+        return;

+    }

     if (dynamic_exists(DT_FINI_ARRAY)) {

         auto funcs = dynamic_ptr<void (*)()>(DT_FINI_ARRAY);

         auto nr = dynamic_val(DT_FINI_ARRAYSZ) / sizeof(*funcs);

@@ -1113,6 +1116,11 @@ void object::run_fini_funcs()

             reinterpret_cast<void(*)()>(func)();

         }

     }

+    for (auto dep : _fini_objects) {

+        dep->run_fini_funcs(); 

+    }

+    _finalized = true;

 }

 

 void* object::tls_addr()

@@ -1397,8 +1405,14 @@ void program::init_library(int argc, char** argv)

             loaded_objects[i]->setprivate(true);

         }

         for (int i = size - 1; i >= 0; i--) {

             loaded_objects[i]->run_init_funcs(argc, argv);

         }

+        if (size > 0) {

+            for (unsigned i = 1; i < size; i++) {

+                loaded_objects[0]->add_fini_object(loaded_objects[i].get());

+            }

+        }

         for (unsigned i = 0; i < size; i++) {

             loaded_objects[i]->setprivate(false);

         }

The essence of the patch is to capture the order in which objects should be finalized which is the exact opposite of the one in which INIT functions are called. 

The good part is that it fixes the tests and seems to prove that the order of finalization was the culprit of the crashes. The bad part is that I am not convinced it is correct because I think it prematurely executes FINI functions.

Imagine a scenario like this with two chains of dependencies between objects:

A -> B -> C -> D -> E 

               F -> D ->E

where A gets removed but F stays in use longer. In which case we call FINI for A, B, C, D, E even though D and E is still in use by F.

I am not sure how to implement it yet, but in general, we should remember the FINI order for all the objects, not just the top ones as my patch does. And then somehow detect if dependant objects are about to be removed per unload_needed() and only call FINI functions for those in the remembered order. 

So in the scenario above in run_fini_funcs() on behalf of A, call run_fini_funcs() for B and C only in that order and stop here. Then only when F is removed and its run_fini_funcs() called, call run_fini_funcs for D and E in that order. The key is how would know ahead of   run_fini_funcs that for example B and C are to removed but D and E not yet.

How to accomplish that I am not sure.

[Waldek Kozaczuk]

After experimenting a lot and trying various things here is the small patch that seems to fix this issue:

diff --git a/core/elf.cc b/core/elf.cc

index 9a26a2e7..37e72519 100644

--- a/core/elf.cc

+++ b/core/elf.cc

@@ -1021,8 +1021,10 @@ void object::load_needed(std::vector<std::shared_ptr<object>>& loaded_objects)

 void object::unload_needed()

 {

-    _needed.clear();

     _used_by_resolve_plt_got.clear();

+    while (!_needed.empty()) {

+        _needed.pop_back();

+    }

 }

 

 ulong object::get_tls_size()

As you can see in essence this patch slightly changes the order in which dependant objects are unloaded. It reverses the order of unloading objects in DT_NEEDED list.

Obviously this also changes the order in which FINI functions are called (or objects finalized). But I am not sure the wrong order of executing the FINI functions was really the issue or order of unloading which affected the execution?

I did play to manually force certain order of executing INIT functions to make it what it should be per #334 and it did not seem to matter. The unloading order seems to be the key.

Also, I even try to reverse the order in DT_NEEDE like so:

 $(boost-tests:%=$(out)/tests/%): LIBS += \

-       -lboost_unit_test_framework \

-       -lboost_filesystem

+       -lboost_filesystem \

+       -lboost_unit_test_framework

and with new patch the all tests would also pass with both boost 1.69 and 1.67

Please note that with boost 1.69 we have more elaborate chains of dependencies with new libraries like boost_chrono and boost_timer so that is possibly why we see these crashes only with boost 1.69.