tests: make check failure #13263

mruddy commented at 12:07 PM on May 17, 2018: contributor

i'm able to reproduce this by running make -j 4 check

Running tests: cuckoocache_tests from test/cuckoocache_tests.cpp
Running tests: DoS_tests from test/DoS_tests.cpp
Running tests: getarg_tests from test/getarg_tests.cpp
Running tests: hash_tests from test/hash_tests.cpp
Running tests: key_io_tests from test/key_io_tests.cpp
Running tests: key_tests from test/key_tests.cpp
Running tests: limitedmap_tests from test/limitedmap_tests.cpp
Running tests: dbwrapper_tests from test/dbwrapper_tests.cpp
Running tests: main_tests from test/main_tests.cpp
Running tests: mempool_tests from test/mempool_tests.cpp
Running tests: merkle_tests from test/merkle_tests.cpp
Running tests: merkleblock_tests from test/merkleblock_tests.cpp
Running tests: miner_tests from test/miner_tests.cpp
Running tests: multisig_tests from test/multisig_tests.cpp
Running tests: net_tests from test/net_tests.cpp
Running tests: netbase_tests from test/netbase_tests.cpp
Running tests: pmt_tests from test/pmt_tests.cpp
Running tests: policyestimator_tests from test/policyestimator_tests.cpp
Running tests: pow_tests from test/pow_tests.cpp
Running tests: prevector_tests from test/prevector_tests.cpp
Running tests: raii_event_tests from test/raii_event_tests.cpp
Running tests: random_tests from test/random_tests.cpp
Running tests: reverselock_tests from test/reverselock_tests.cpp
Running tests: rpc_tests from test/rpc_tests.cpp
Running tests: sanity_tests from test/sanity_tests.cpp
Running tests: scheduler_tests from test/scheduler_tests.cpp
Running tests: script_P2SH_tests from test/script_P2SH_tests.cpp
Running tests: script_tests from test/script_tests.cpp
Running tests: script_standard_tests from test/script_standard_tests.cpp
Running tests: scriptnum_tests from test/scriptnum_tests.cpp
Running tests: serialize_tests from test/serialize_tests.cpp
Running tests: sighash_tests from test/sighash_tests.cpp
Running tests: sigopcount_tests from test/sigopcount_tests.cpp
Running tests: skiplist_tests from test/skiplist_tests.cpp
Running tests: streams_tests from test/streams_tests.cpp
Running tests: timedata_tests from test/timedata_tests.cpp
Running tests: torcontrol_tests from test/torcontrol_tests.cpp
Running tests: transaction_tests from test/transaction_tests.cpp
Running tests: txindex_tests from test/txindex_tests.cpp
Running tests: txvalidation_tests from test/txvalidation_tests.cpp
Running tests: tx_validationcache_tests from test/txvalidationcache_tests.cpp
Running tests: uint256_tests from test/uint256_tests.cpp
Running tests: util_tests from test/util_tests.cpp
Running tests: validation_block_tests from test/validation_block_tests.cpp
Running tests: versionbits_tests from test/versionbits_tests.cpp
/bin/bash: line 1: 24432 Aborted                 (core dumped) test/test_bitcoin -l test_suite -t "`cat test/validation_block_tests.cpp | grep "BOOST_FIXTURE_TEST_SUITE(\|BOOST_AUTO_TEST_SUITE(" | cut -d '(' -f 2 | cut -d ',' -f 1 | cut -d ')' -f 1`" > test/validation_block_tests.cpp.log 2>&1
Running 1 test case...
Entering test module "Bitcoin Test Suite"
test/validation_block_tests.cpp(21): Entering test suite "validation_block_tests"
test/validation_block_tests.cpp(122): Entering test case "processnewblock_signals_ordering"
*** stack smashing detected ***: <unknown> terminated
*** stack smashing detected ***: <unknown> terminated
unknown location(0): fatal error: in "validation_block_tests/processnewblock_signals_ordering": memory access violation at address: 0xffffffff: no mapping at fault address
test/validation_block_tests.cpp(137): last checkpoint
Test is aborted
test/validation_block_tests.cpp(122): Leaving test case "processnewblock_signals_ordering"; testing time: 23187us
Test is aborted
test/validation_block_tests.cpp(21): Leaving test suite "validation_block_tests"; testing time: 23205us
Test is aborted
Leaving test module "Bitcoin Test Suite"; testing time: 23252us

*** 1 failure is detected in the test module "Bitcoin Test Suite"
test_bitcoin: /usr/include/boost/thread/pthread/condition_variable_fwd.hpp:116: boost::condition_variable::~condition_variable(): Assertion `!ret' failed.
Makefile:10248: recipe for target 'test/validation_block_tests.cpp.test' failed
make[3]: *** [test/validation_block_tests.cpp.test] Error 1

this is all the test log has:

> cat src/test-suite.log
==============================================
   Bitcoin Core 0.16.99: src/test-suite.log
==============================================

# TOTAL: 1
# PASS:  1
# SKIP:  0
# XFAIL: 0
# FAIL:  0
# XPASS: 0
# ERROR: 0

.. contents:: :depth: 2

more info:

Ubuntu 18.04 LTS x86_64

> apt-cache show libboost-thread-dev
Package: libboost-thread-dev
Architecture: amd64
Version: 1.65.1.0ubuntu1
Multi-Arch: same
Priority: optional
Section: libdevel
Source: boost-defaults
Origin: Ubuntu
Maintainer: Ubuntu Developers <ubuntu-devel-discuss@lists.ubuntu.com>
Original-Maintainer: Debian Boost Team <pkg-boost-devel@lists.alioth.debian.org>
Bugs: https://bugs.launchpad.net/ubuntu/+filebug
Installed-Size: 10
Depends: libboost-thread1.65-dev
Filename: pool/main/b/boost-defaults/libboost-thread-dev_1.65.1.0ubuntu1_amd64.deb
Size: 2948
MD5sum: 960037cf0c14983eb7e6234d2fe1464f
SHA1: 87c8e9817842a7d551774eeb472ad2369cd61cb8
SHA256: 427d72389553cff392c9362230f12c2bcfb5e65819ad81e773db91060413e4a6

fanquake added the label Tests on May 17, 2018

fanquake added the label Linux/Unix on May 17, 2018

mruddy commented at 12:10 PM on May 17, 2018: contributor

forgot to add that this is with the latest master commit 4cfe17c3382ba750131cdc8703b2978132822070

MarcoFalke commented at 11:52 AM on May 18, 2018: member

Does this happen with ./src/test/test_bitcoin -t validation_block_tests/processnewblock_signals_ordering as well? In this case you could run through valgrind or gdb

mruddy commented at 1:34 PM on May 18, 2018: contributor

@MarcoFalke yes, it does happen with that command.

1st run: it hung for a couple of minutes and then i gave it ctrl+c

> ./src/test/test_bitcoin -t validation_block_tests/processnewblock_signals_ordering
Running 1 test case...
test_bitcoin: malloc.c:3079: __libc_malloc: Assertion `!victim || chunk_is_mmapped (mem2chunk (victim)) || ar_ptr == arena_for_chunk (mem2chunk (victim))' failed.
*** stack smashing detected ***: <unknown> terminated
unknown location(0): fatal error: in "validation_block_tests/processnewblock_signals_ordering": memory access violation at address: 0x0000148a: no mapping at fault address
test/validation_block_tests.cpp(137): last checkpoint
^C

2nd run: it aborted very quickly

> ./src/test/test_bitcoin -t validation_block_tests/processnewblock_signals_ordering
Running 1 test case...
unknown location(0): fatal error: in "validation_block_tests/processnewblock_signals_ordering": signal: generated by kill() (or family); uid=0; pid=0
test/validation_block_tests.cpp(137): last checkpoint

*** 1 failure is detected in the test module "Bitcoin Test Suite"
test_bitcoin: /usr/include/boost/thread/pthread/condition_variable_fwd.hpp:116: boost::condition_variable::~condition_variable(): Assertion `!ret' failed.
Aborted (core dumped)

then i ran valgrind and got the attached log file valgrind.txt :

valgrind --suppressions=contrib/valgrind.supp --leak-check=full --show-leak-kinds=all ./src/test/test_bitcoin -t validation_block_tests/processnewblock_signals_ordering > ../valgrind.txt 2>&1
Segmentation fault (core dumped)

mruddy commented at 10:12 AM on May 21, 2018: contributor

Downgrading from libboost1.65-dev:amd64 to libboost1.62-dev:amd64 does NOT fix this. Upgrading to boost_1_67_0 built from source does NOT fix this either.

MarcoFalke commented at 1:58 PM on May 21, 2018: member

I couldn't reproduce and I doubt it has something to do with boost. You might want to fiddle around with the code in the lambda or test case: https://github.com/bitcoin/bitcoin/blob/11e7bdfd903ef342c0ff2dcd062d6eab8dd25350/src/test/validation_block_tests.cpp#L160 (E.g. replace [] with .at(), as a first try) Not sure what to look out for, since I don't see how this test failure could happen.

mruddy commented at 6:07 PM on May 21, 2018: contributor

I did some narrowing down by commenting lines out and running: ./src/test/test_bitcoin -t validation_block_tests/processnewblock_signals_ordering

When I comment only this one line, the errors stop: https://github.com/bitcoin/bitcoin/blob/master/src/validation.cpp#L3508

Something about that AssertLockNotHeld.

mruddy commented at 6:40 PM on May 21, 2018: contributor

@MarcoFalke I think the enable-debug configure flag might be involved with the cause. When I configured without it, I did not get the failure. Can you try this and see if you can reproduce?:

make clean
./autogen.sh
./configure --enable-debug
make check     (or use "make -j 4 check", if you want to save time)

MarcoFalke commented at 10:47 PM on May 21, 2018: member

Interesting. This does not happen when compiled from depends, which also explains that travis didn't hit this issue.

marcoagner commented at 10:58 PM on May 21, 2018: contributor

I was able to reproduce this issue both under 4cfe17c and current master tip.

I don't have the time to look further into it right now but, running under gdb, it segfaults when reaching sync.cpp:165 on a new thread (e.g. 5). Setting a break on this line, right before the crash, lockstack is:

>>> p lockstack
$2 = std::unique_ptr<std::vector<std::pair<void*, CLockLocation>, std::allocator<std::pair<void*, CLockLocation> > >> containing 0x0

and then, surely, it crashes on next step.

MarcoFalke added this to the milestone 0.17.0 on May 22, 2018

MarcoFalke removed the label Linux/Unix on May 22, 2018

practicalswift commented at 9:55 PM on May 22, 2018: contributor

@MarcoFalke, are you able to reproduce this issue?

It seems like stack-protector kicks in for @mruddy (*** stack smashing detected ***) when running the processnewblock_signals_ordering test, but shouldn't it kick in for all of us? What special steps needs to be taken to reproduce reliably? :-)

MarcoFalke commented at 10:03 PM on May 22, 2018: member

@practicalswift The code is only compiled, when running with --enable-debug or the DEBUG_LOCKORDER switch turned on. As mentioned above, I couldn't reproduce when building from depends.

You can then reproduce by running that test case or a test case which doesn't take any locks, but calls AssertLock(Not)Held

laanwj commented at 2:29 PM on May 28, 2018: member

Fixed by #13300

laanwj closed this on May 28, 2018

MarcoFalke locked this on Sep 8, 2021