bahman/scylla
1
0
Fork 0
Code Issues Pull Requests Actions 3 Packages Projects Releases Wiki Activity

test: stop using BOOST_TEST_MESSAGE() for logging

Browse Source 
We use boost test logging primarily to generate nice XML xunit
files used in Jenkins. These XML files can be bloated
with messages from BOOST_TEST_MESSAGE(), hundreds of megabytes
of build archives, on every build.

Let's use seastar logger for test logging instead, reserving
the use of boost log facilities for boost test markup information.
This commit is contained in:
Konstantin Osipov
2020-03-03 23:41:51 +03:00
parent 325c3e13eb
commit ff3f9cb7cf
25 changed files with 235 additions and 153 deletions
Download Patch File Download Diff File Expand all files Collapse all files

19
configure.py
View File

@@ -872,6 +872,7 @@ headers = find_headers('.', excluded_dirs=['idl', 'build', 'seastar', '.git'])
scylla_tests_generic_dependencies = [
'test/lib/cql_test_env.cc',
'test/lib/test_services.cc',
'test/lib/log.cc',
]
scylla_tests_dependencies = scylla_core + idls + scylla_tests_generic_dependencies + [
@@ -963,7 +964,13 @@ deps['test/boost/sstable_test'] += ['test/lib/sstable_utils.cc', 'test/lib/norma
deps['test/boost/sstable_datafile_test'] += ['test/lib/sstable_utils.cc', 'test/lib/normalizing_reader.cc']
deps['test/boost/mutation_reader_test'] += ['test/lib/sstable_utils.cc']
deps['test/boost/bytes_ostream_test'] = ['test/boost/bytes_ostream_test.cc', 'utils/managed_bytes.cc', 'utils/logalloc.cc', 'utils/dynamic_bitset.cc']
deps['test/boost/bytes_ostream_test'] = [
"test/boost/bytes_ostream_test.cc",
"utils/managed_bytes.cc",
"utils/logalloc.cc",
"utils/dynamic_bitset.cc",
"test/lib/log.cc",
]
deps['test/boost/input_stream_test'] = ['test/boost/input_stream_test.cc']
deps['test/boost/UUID_test'] = ['utils/UUID_gen.cc', 'test/boost/UUID_test.cc', 'utils/uuid.cc', 'utils/managed_bytes.cc', 'utils/logalloc.cc', 'utils/dynamic_bitset.cc', 'hashers.cc']
deps['test/boost/murmur_hash_test'] = ['bytes.cc', 'utils/murmur_hash.cc', 'test/boost/murmur_hash_test.cc']
@@ -974,12 +981,18 @@ deps['test/perf/perf_fast_forward'] += ['release.cc']
deps['test/perf/perf_simple_query'] += ['release.cc']
deps['test/boost/meta_test'] = ['test/boost/meta_test.cc']
deps['test/manual/imr_test'] = ['test/manual/imr_test.cc', 'utils/logalloc.cc', 'utils/dynamic_bitset.cc']
deps['test/boost/reusable_buffer_test'] = ['test/boost/reusable_buffer_test.cc']
deps['test/boost/reusable_buffer_test'] = [
"test/boost/reusable_buffer_test.cc",
"test/lib/log.cc",
]
deps['test/boost/utf8_test'] = ['utils/utf8.cc', 'test/boost/utf8_test.cc']
deps['test/boost/small_vector_test'] = ['test/boost/small_vector_test.cc']
deps['test/boost/multishard_mutation_query_test'] += ['test/boost/test_table.cc']
deps['test/boost/vint_serialization_test'] = ['test/boost/vint_serialization_test.cc', 'vint-serialization.cc', 'bytes.cc']
deps['test/boost/linearizing_input_stream_test'] = ['test/boost/linearizing_input_stream_test.cc']
deps['test/boost/linearizing_input_stream_test'] = [
"test/boost/linearizing_input_stream_test.cc",
"test/lib/log.cc",
]
deps['test/boost/duration_test'] += ['test/lib/exception_utils.cc']

3
test/boost/bytes_ostream_test.cc
View File

@@ -30,6 +30,7 @@
#include "serializer_impl.hh"
#include "test/lib/random_utils.hh"
#include "test/lib/log.hh"
void append_sequence(bytes_ostream& buf, int count) {
for (int i = 0; i < count; i++) {
@@ -284,7 +285,7 @@ BOOST_AUTO_TEST_CASE(test_append_big_and_small_chunks) {
BOOST_AUTO_TEST_CASE(test_remove_suffix) {
auto test = [] (size_t length, size_t suffix) {
BOOST_TEST_MESSAGE("Testing buffer size " << length << " and suffix size " << suffix);
testlog.info("Testing buffer size {} and suffix size {}", length, suffix);
auto data = tests::random::get_bytes(length);
bytes_view view = data;

9
test/boost/cdc_test.cc
View File

@@ -29,6 +29,7 @@
#include "test/lib/cql_assertions.hh"
#include "test/lib/cql_test_env.hh"
#include "test/lib/exception_utils.hh"
#include "test/lib/log.hh"
#include "transport/messages/result_message.hh"
#include "types.hh"
@@ -217,7 +218,7 @@ SEASTAR_THREAD_TEST_CASE(test_detecting_conflict_of_cdc_log_table_with_existing_
SEASTAR_THREAD_TEST_CASE(test_permissions_of_cdc_log_table) {
do_with_cql_env_thread([] (cql_test_env& e) {
auto assert_unauthorized = [&e] (const sstring& stmt) {
BOOST_TEST_MESSAGE(format("Must throw unauthorized_exception: {}", stmt));
testlog.info("Must throw unauthorized_exception: {}", stmt);
BOOST_REQUIRE_THROW(e.execute_cql(stmt).get(), exceptions::unauthorized_exception);
};
@@ -263,7 +264,7 @@ SEASTAR_THREAD_TEST_CASE(test_permissions_of_cdc_description) {
do_with_cql_env_thread([] (cql_test_env& e) {
auto test_table = [&e] (const sstring& table_name) {
auto assert_unauthorized = [&e] (const sstring& stmt) {
BOOST_TEST_MESSAGE(format("Must throw unauthorized_exception: {}", stmt));
testlog.info("Must throw unauthorized_exception: {}", stmt);
BOOST_REQUIRE_THROW(e.execute_cql(stmt).get(), exceptions::unauthorized_exception);
};
@@ -514,8 +515,8 @@ SEASTAR_THREAD_TEST_CASE(test_range_deletion) {
size_t row_idx = 0;
auto check_row = [&](int32_t ck, cdc::operation operation) {
BOOST_TEST_MESSAGE(format("{}", results[row_idx][ck_index]));
BOOST_TEST_MESSAGE(format("{}", bytes_opt(ck_type->decompose(ck))));
testlog.trace("{}", results[row_idx][ck_index]);
testlog.trace("{}", bytes_opt(ck_type->decompose(ck)));
BOOST_REQUIRE_EQUAL(results[row_idx][ck_index], bytes_opt(ck_type->decompose(ck)));
BOOST_REQUIRE_EQUAL(results[row_idx][op_index], bytes_opt(op_type->decompose(std::underlying_type_t<cdc::operation>(operation))));
++row_idx;

21
test/boost/cql_query_test.cc
View File

@@ -33,6 +33,7 @@
#include <seastar/testing/thread_test_case.hh>
#include "test/lib/cql_test_env.hh"
#include "test/lib/cql_assertions.hh"
#include "test/lib/log.hh"
#include <seastar/core/future-util.hh>
#include <seastar/core/sleep.hh>
@@ -4417,28 +4418,28 @@ SEASTAR_TEST_CASE(test_int_sum_with_cast) {
SEASTAR_TEST_CASE(test_float_sum_overflow) {
return do_with_cql_env_thread([] (cql_test_env& e) {
cquery_nofail(e, "create table cf (pk text, val float, primary key(pk));");
BOOST_TEST_MESSAGE("make sure we can sum close to the max value");
testlog.info("make sure we can sum close to the max value");
cquery_nofail(e, "insert into cf (pk, val) values ('a', 3.4028234e+38);");
auto result = e.execute_cql("select sum(val) from cf;").get0();
assert_that(result)
.is_rows()
.with_size(1)
.with_row({serialized(3.4028234e+38f)});
BOOST_TEST_MESSAGE("cause overflow");
testlog.info("cause overflow");
cquery_nofail(e, "insert into cf (pk, val) values ('b', 1e+38);");
result = e.execute_cql("select sum(val) from cf;").get0();
assert_that(result)
.is_rows()
.with_size(1)
.with_row({serialized(std::numeric_limits<float>::infinity())});
BOOST_TEST_MESSAGE("test maximum negative value");
testlog.info("test maximum negative value");
cquery_nofail(e, "insert into cf (pk, val) values ('a', -3.4028234e+38);");
result = e.execute_cql("select sum(val) from cf;").get0();
assert_that(result)
.is_rows()
.with_size(1)
.with_row({serialized(-2.4028234e+38f)});
BOOST_TEST_MESSAGE("cause negative overflow");
testlog.info("cause negative overflow");
cquery_nofail(e, "insert into cf (pk, val) values ('c', -2e+38);");
result = e.execute_cql("select sum(val) from cf;").get0();
assert_that(result)
@@ -4451,28 +4452,28 @@ SEASTAR_TEST_CASE(test_float_sum_overflow) {
SEASTAR_TEST_CASE(test_double_sum_overflow) {
return do_with_cql_env_thread([] (cql_test_env& e) {
cquery_nofail(e, "create table cf (pk text, val double, primary key(pk));");
BOOST_TEST_MESSAGE("make sure we can sum close to the max value");
testlog.info("make sure we can sum close to the max value");
cquery_nofail(e, "insert into cf (pk, val) values ('a', 1.79769313486231570814527423732e+308);");
auto result = e.execute_cql("select sum(val) from cf;").get0();
assert_that(result)
.is_rows()
.with_size(1)
.with_row({serialized(1.79769313486231570814527423732E308)});
BOOST_TEST_MESSAGE("cause overflow");
testlog.info("cause overflow");
cquery_nofail(e, "insert into cf (pk, val) values ('b', 0.5e+308);");
result = e.execute_cql("select sum(val) from cf;").get0();
assert_that(result)
.is_rows()
.with_size(1)
.with_row({serialized(std::numeric_limits<double>::infinity())});
BOOST_TEST_MESSAGE("test maximum negative value");
testlog.info("test maximum negative value");
cquery_nofail(e, "insert into cf (pk, val) values ('a', -1.79769313486231570814527423732e+308);");
result = e.execute_cql("select sum(val) from cf;").get0();
assert_that(result)
.is_rows()
.with_size(1)
.with_row({serialized(-1.29769313486231570814527423732e+308)});
BOOST_TEST_MESSAGE("cause negative overflow");
testlog.info("cause negative overflow");
cquery_nofail(e, "insert into cf (pk, val) values ('c', -1e+308);");
result = e.execute_cql("select sum(val) from cf;").get0();
assert_that(result)
@@ -4786,7 +4787,7 @@ shared_ptr<cql_transport::messages::result_message> cql_func_require_nofail(
} else {
res = env.execute_cql(query).get0();
}
BOOST_TEST_MESSAGE(format("Query '{}' succeeded as expected", query));
testlog.info("Query '{}' succeeded as expected", query);
} catch (...) {
BOOST_ERROR(format("query '{}' failed unexpectedly with error: {}\n{}:{}: originally from here",
query, std::current_exception(),
@@ -4813,7 +4814,7 @@ void cql_func_require_throw(
BOOST_ERROR(format("query '{}' succeeded unexpectedly\n{}:{}: originally from here", query,
loc.file_name(), loc.line()));
} catch (Exception& e) {
BOOST_TEST_MESSAGE(format("Query '{}' failed as expected with error: {}", query, e));
testlog.info("Query '{}' failed as expected with error: {}", query, e);
} catch (...) {
BOOST_ERROR(format("query '{}' failed with unexpected error: {}\n{}:{}: originally from here",
query, std::current_exception(),

3
test/boost/data_listeners_test.cc
View File

@@ -24,6 +24,7 @@
#include <seastar/testing/test_case.hh>
#include "test/lib/cql_test_env.hh"
#include "test/lib/cql_assertions.hh"
#include "test/lib/log.hh"
#include "cql3/query_processor.hh"
#include "db/data_listeners.hh"
@@ -31,8 +32,6 @@
using namespace std;
using namespace std::chrono_literals;
logging::logger testlog("test");
class table_listener : public db::data_listener {
sstring _cf_name;

25
test/boost/flat_mutation_reader_test.cc
View File

@@ -38,6 +38,7 @@
#include "test/lib/test_services.hh"
#include "test/lib/simple_schema.hh"
#include "test/lib/flat_mutation_reader_assertions.hh"
#include "test/lib/log.hh"
struct mock_consumer {
struct result {
@@ -439,14 +440,14 @@ SEASTAR_TEST_CASE(test_multi_range_reader) {
// Generator ranges are single pass, so we need a new range each time they are used.
auto run_test = [&] (auto make_empty_ranges, auto make_single_ranges, auto make_multiple_ranges) {
BOOST_TEST_MESSAGE("empty ranges");
testlog.info("empty ranges");
assert_that(make_flat_multi_range_reader(s.schema(), source, make_empty_ranges(), s.schema()->full_slice()))
.produces_end_of_stream()
.fast_forward_to(fft_range)
.produces(ms[9])
.produces_end_of_stream();
BOOST_TEST_MESSAGE("single range");
testlog.info("single range");
assert_that(make_flat_multi_range_reader(s.schema(), source, make_single_ranges(), s.schema()->full_slice()))
.produces(ms[1])
.produces(ms[2])
@@ -455,7 +456,7 @@ SEASTAR_TEST_CASE(test_multi_range_reader) {
.produces(ms[9])
.produces_end_of_stream();
BOOST_TEST_MESSAGE("read full partitions and fast forward");
testlog.info("read full partitions and fast forward");
assert_that(make_flat_multi_range_reader(s.schema(), source, make_multiple_ranges(), s.schema()->full_slice()))
.produces(ms[1])
.produces(ms[2])
@@ -465,7 +466,7 @@ SEASTAR_TEST_CASE(test_multi_range_reader) {
.produces(ms[9])
.produces_end_of_stream();
BOOST_TEST_MESSAGE("read, skip partitions and fast forward");
testlog.info("read, skip partitions and fast forward");
assert_that(make_flat_multi_range_reader(s.schema(), source, make_multiple_ranges(), s.schema()->full_slice()))
.produces_partition_start(keys[1])
.next_partition()
@@ -484,13 +485,13 @@ SEASTAR_TEST_CASE(test_multi_range_reader) {
.produces_end_of_stream();
};
BOOST_TEST_MESSAGE("vector version");
testlog.info("vector version");
run_test(
[&] { return empty_ranges; },
[&] { return single_ranges; },
[&] { return multiple_ranges; });
BOOST_TEST_MESSAGE("generator version");
testlog.info("generator version");
run_test(
[&] { return empty_generator; },
[&] { return single_generator; },
@@ -597,12 +598,12 @@ void test_flat_stream(schema_ptr s, std::vector<mutation> muts, reversed_partiti
}
};
BOOST_TEST_MESSAGE(format("Consume all{}", reversed_msg));
testlog.info("Consume all{}", reversed_msg);
auto fmr = flat_mutation_reader_from_mutations(muts);
auto muts2 = consume_fn(fmr, flat_stream_consumer(s, reversed));
BOOST_REQUIRE_EQUAL(muts, muts2);
BOOST_TEST_MESSAGE(format("Consume first fragment from partition{}", reversed_msg));
testlog.info("Consume first fragment from partition{}", reversed_msg);
fmr = flat_mutation_reader_from_mutations(muts);
muts2 = consume_fn(fmr, flat_stream_consumer(s, reversed, skip_after_first_fragment::yes));
BOOST_REQUIRE_EQUAL(muts.size(), muts2.size());
@@ -615,7 +616,7 @@ void test_flat_stream(schema_ptr s, std::vector<mutation> muts, reversed_partiti
BOOST_REQUIRE_EQUAL(m, muts[j]);
}
BOOST_TEST_MESSAGE(format("Consume first partition{}", reversed_msg));
testlog.info("Consume first partition{}", reversed_msg);
fmr = flat_mutation_reader_from_mutations(muts);
muts2 = consume_fn(fmr, flat_stream_consumer(s, reversed, skip_after_first_fragment::no,
skip_after_first_partition::yes));
@@ -631,7 +632,7 @@ void test_flat_stream(schema_ptr s, std::vector<mutation> muts, reversed_partiti
}
return true;
});
BOOST_TEST_MESSAGE("Consume all, filtered");
testlog.info("Consume all, filtered");
fmr = flat_mutation_reader_from_mutations(muts);
muts2 = fmr.consume_in_thread(flat_stream_consumer(s, reversed), std::move(filter), db::no_timeout);
BOOST_REQUIRE_EQUAL(muts.size() / 2, muts2.size());
@@ -802,7 +803,7 @@ SEASTAR_THREAD_TEST_CASE(test_reverse_reader_memory_limit) {
};
auto test_with_partition = [&] (bool with_static_row) {
BOOST_TEST_MESSAGE(fmt::format("Testing with_static_row={}", with_static_row));
testlog.info("Testing with_static_row={}", with_static_row);
auto mut = schema.new_mutation("pk1");
const size_t desired_mut_size = 1 * 1024 * 1024;
const size_t row_size = 10 * 1024;
@@ -822,7 +823,7 @@ SEASTAR_THREAD_TEST_CASE(test_reverse_reader_memory_limit) {
reverse_reader.consume(phony_consumer{}, db::no_timeout).get();
BOOST_FAIL("No exception thrown for reversing overly big partition");
} catch (const std::runtime_error& e) {
BOOST_TEST_MESSAGE(fmt::format("Got exception with message: {}", e.what()));
testlog.info("Got exception with message: {}", e.what());
auto str = sstring(e.what());
BOOST_REQUIRE_EQUAL(str.find("Aborting reverse partition read because partition pk1"), 0);
} catch (...) {

11
test/boost/linearizing_input_stream_test.cc
View File

@@ -29,6 +29,7 @@
#include "utils/linearizing_input_stream.hh"
#include "utils/serialization.hh"
#include "test/lib/random_utils.hh"
#include "test/lib/log.hh"
namespace {
@@ -177,13 +178,13 @@ const payload generate_payload(std::mt19937& rnd_engine) {
}
std::vector<bytes> no_fragmenting(std::mt19937&, bytes_view bv) {
BOOST_TEST_MESSAGE(fmt::format("Fragmenting payload with {}()", __FUNCTION__));
testlog.info("Fragmenting payload with {}()", __FUNCTION__);
return {bytes{bv}};
}
template <size_t N>
std::vector<bytes> n_byte_fragments(std::mt19937&, bytes_view bv) {
BOOST_TEST_MESSAGE(fmt::format("Fragmenting payload with {}<{}>()", __FUNCTION__, N));
testlog.info("Fragmenting payload with {}<{}>()", __FUNCTION__, N);
std::vector<bytes> ret;
while (!bv.empty()) {
const auto size = std::min(bv.size(), N);
@@ -194,7 +195,7 @@ std::vector<bytes> n_byte_fragments(std::mt19937&, bytes_view bv) {
}
std::vector<bytes> random_fragments(std::mt19937& rnd_engine, bytes_view bv) {
BOOST_TEST_MESSAGE(fmt::format("Fragmenting payload with {}()", __FUNCTION__));
testlog.info("Fragmenting payload with {}()", __FUNCTION__);
std::vector<bytes> ret;
while (!bv.empty()) {
std::uniform_int_distribution<size_t> size_dist{1, bv.size()};
@@ -217,14 +218,14 @@ BOOST_AUTO_TEST_CASE(test_linearizing_input_stream) {
auto payload = generate_payload(rnd_engine);
std::uniform_int_distribution<uint8_t> skip_dist{0, 1};
BOOST_TEST_MESSAGE("Read back data");
testlog.info("Read back data");
for (auto&& fragment_fn : {no_fragmenting, n_byte_fragments<1>, n_byte_fragments<2>, n_byte_fragments<3>, random_fragments}) {
size_t expected_size = payload.data.size();
auto fragmented_payload = fragment_vector(fragment_fn(rnd_engine, payload.data));
auto in = utils::linearizing_input_stream(fragmented_payload);
BOOST_TEST_MESSAGE(fmt::format("Testing with payload: size={}, fragments={}", expected_size, fragmented_payload.fragments()));
testlog.info("Testing with payload: size={}, fragments={}", expected_size, fragmented_payload.fragments());
BOOST_REQUIRE_EQUAL(fragmented_payload.size_bytes(), expected_size);
BOOST_REQUIRE_EQUAL(in.size(), expected_size);

33
test/boost/logalloc_test.cc
View File

@@ -39,6 +39,7 @@
#include "utils/logalloc.hh"
#include "utils/managed_ref.hh"
#include "utils/managed_bytes.hh"
#include "test/lib/log.hh"
#include "log.hh"
[[gnu::unused]]
@@ -662,32 +663,32 @@ SEASTAR_TEST_CASE(test_region_groups_basic_throttling) {
big_region->alloc();
// We should not be permitted to go forward with a new allocation now...
BOOST_TEST_MESSAGE(format("now = {}", lowres_clock::now().time_since_epoch().count()));
testlog.info("now = {}", lowres_clock::now().time_since_epoch().count());
fut = simple.run_when_memory_available([&simple_region] { simple_region->alloc_small(); }, db::no_timeout);
BOOST_REQUIRE_EQUAL(fut.available(), false);
BOOST_REQUIRE_GT(simple.memory_used(), logalloc::segment_size);
BOOST_TEST_MESSAGE(format("now = {}", lowres_clock::now().time_since_epoch().count()));
BOOST_TEST_MESSAGE(format("used = {}", simple.memory_used()));
testlog.info("now = {}", lowres_clock::now().time_since_epoch().count());
testlog.info("used = {}", simple.memory_used());
BOOST_TEST_MESSAGE("Resetting");
testlog.info("Resetting");
// But when we remove the big bytes allocator from the region, then we should.
// Internally, we can't guarantee that just freeing the object will give the segment back,
// that's up to the internal policies. So to make sure we need to remove the whole region.
big_region.reset();
BOOST_TEST_MESSAGE(format("used = {}", simple.memory_used()));
BOOST_TEST_MESSAGE(format("now = {}", lowres_clock::now().time_since_epoch().count()));
testlog.info("used = {}", simple.memory_used());
testlog.info("now = {}", lowres_clock::now().time_since_epoch().count());
try {
quiesce(std::move(fut));
} catch (...) {
BOOST_TEST_MESSAGE(format("Aborting: {}", std::current_exception()));
BOOST_TEST_MESSAGE(format("now = {}", lowres_clock::now().time_since_epoch().count()));
BOOST_TEST_MESSAGE(format("used = %d", simple.memory_used()));
testlog.info("Aborting: {}", std::current_exception());
testlog.info("now = {}", lowres_clock::now().time_since_epoch().count());
testlog.info("used = {}", simple.memory_used());
abort();
}
BOOST_TEST_MESSAGE(format("now = {}", lowres_clock::now().time_since_epoch().count()));
testlog.info("now = {}", lowres_clock::now().time_since_epoch().count());
});
}
@@ -1272,22 +1273,22 @@ SEASTAR_TEST_CASE(test_zone_reclaiming_preserves_free_size) {
objs.emplace_back(managed_bytes(managed_bytes::initialized_later(), 1024));
}
BOOST_TEST_MESSAGE(logalloc::shard_tracker().non_lsa_used_space());
BOOST_TEST_MESSAGE(logalloc::shard_tracker().region_occupancy());
testlog.info("non_lsa_used_space = {}", logalloc::shard_tracker().non_lsa_used_space());
testlog.info("region_occupancy = {}", logalloc::shard_tracker().region_occupancy());
while (logalloc::shard_tracker().region_occupancy().used_space() >= logalloc::segment_size * 2) {
objs.pop_front();
}
BOOST_TEST_MESSAGE(logalloc::shard_tracker().non_lsa_used_space());
BOOST_TEST_MESSAGE(logalloc::shard_tracker().region_occupancy());
testlog.info("non_lsa_used_space = {}", logalloc::shard_tracker().non_lsa_used_space());
testlog.info("region_occupancy = {}", logalloc::shard_tracker().region_occupancy());
auto before = logalloc::shard_tracker().non_lsa_used_space();
logalloc::shard_tracker().reclaim(logalloc::segment_size);
auto after = logalloc::shard_tracker().non_lsa_used_space();
BOOST_TEST_MESSAGE(logalloc::shard_tracker().non_lsa_used_space());
BOOST_TEST_MESSAGE(logalloc::shard_tracker().region_occupancy());
testlog.info("non_lsa_used_space = {}", logalloc::shard_tracker().non_lsa_used_space());
testlog.info("region_occupancy = {}", logalloc::shard_tracker().region_occupancy());
BOOST_REQUIRE(after <= before);
});

7
test/boost/memtable_test.cc
View File

@@ -36,6 +36,7 @@
#include "flat_mutation_reader.hh"
#include "test/lib/data_model.hh"
#include "test/lib/random_utils.hh"
#include "test/lib/log.hh"
static api::timestamp_type next_timestamp() {
static thread_local api::timestamp_type next_timestamp = 1;
@@ -132,7 +133,7 @@ SEASTAR_TEST_CASE(test_memtable_flush_reader) {
mut.partition().compact_for_compaction(*mut.schema(), always_gc, now);
}
BOOST_TEST_MESSAGE("Simple read");
testlog.info("Simple read");
auto mt = make_memtable(mgr, tbl_stats, muts);
assert_that(mt->make_flush_reader(gen.schema(), default_priority_class()))
@@ -142,7 +143,7 @@ SEASTAR_TEST_CASE(test_memtable_flush_reader) {
.produces_compacted(compacted_muts[3], now)
.produces_end_of_stream();
BOOST_TEST_MESSAGE("Read with next_partition() calls between partition");
testlog.info("Read with next_partition() calls between partition");
mt = make_memtable(mgr, tbl_stats, muts);
assert_that(mt->make_flush_reader(gen.schema(), default_priority_class()))
.next_partition()
@@ -156,7 +157,7 @@ SEASTAR_TEST_CASE(test_memtable_flush_reader) {
.next_partition()
.produces_end_of_stream();
BOOST_TEST_MESSAGE("Read with next_partition() calls inside partitions");
testlog.info("Read with next_partition() calls inside partitions");
mt = make_memtable(mgr, tbl_stats, muts);
assert_that(mt->make_flush_reader(gen.schema(), default_priority_class()))
.produces_compacted(compacted_muts[0], now)

7
test/boost/multishard_mutation_query_test.cc
View File

@@ -29,6 +29,7 @@
#include "test/lib/cql_assertions.hh"
#include "test/lib/mutation_assertions.hh"
#include "test/lib/test_table.hh"
#include "test/lib/log.hh"
#include <seastar/testing/thread_test_case.hh>
@@ -49,7 +50,7 @@ static uint64_t aggregate_querier_cache_stat(distributed<database>& db, uint64_t
static void check_cache_population(distributed<database>& db, size_t queriers,
std::experimental::source_location sl = std::experimental::source_location::current()) {
BOOST_TEST_MESSAGE(format("{}() called from {}() {}:{:d}", __FUNCTION__, sl.function_name(), sl.file_name(), sl.line()));
testlog.info("{}() called from {}() {}:{:d}", __FUNCTION__, sl.function_name(), sl.file_name(), sl.line());
parallel_for_each(boost::irange(0u, smp::count), [queriers, &db] (unsigned shard) {
return db.invoke_on(shard, [queriers] (database& local_db) {
@@ -61,7 +62,7 @@ static void check_cache_population(distributed<database>& db, size_t queriers,
static void require_eventually_empty_caches(distributed<database>& db,
std::experimental::source_location sl = std::experimental::source_location::current()) {
BOOST_TEST_MESSAGE(format("{}() called from {}() {}:{:d}", __FUNCTION__, sl.function_name(), sl.file_name(), sl.line()));
testlog.info("{}() called from {}() {}:{:d}", __FUNCTION__, sl.function_name(), sl.file_name(), sl.line());
auto aggregated_population_is_zero = [&] () mutable {
return aggregate_querier_cache_stat(db, &query::querier_cache::stats::population) == 0;
@@ -228,7 +229,7 @@ void check_results_are_equal(std::vector<mutation>& results1, std::vector<mutati
boost::sort(results1, mut_less);
boost::sort(results2, mut_less);
for (unsigned i = 0; i < results1.size(); ++i) {
BOOST_TEST_MESSAGE(format("Comparing mutation #{:d}", i));
testlog.trace("Comparing mutation #{:d}", i);
assert_that(results2[i]).is_equal_to(results1[i]);
}
}

10
test/boost/mutation_reader_test.cc
View File

@@ -2143,13 +2143,13 @@ SEASTAR_THREAD_TEST_CASE(test_multishard_combining_reader_as_mutation_source) {
};
};
BOOST_TEST_MESSAGE("run_mutation_source_tests(evict_readers=false, single_fragment_buffer=false)");
testlog.info("run_mutation_source_tests(evict_readers=false, single_fragment_buffer=false)");
run_mutation_source_tests(make_populate(false, false));
BOOST_TEST_MESSAGE("run_mutation_source_tests(evict_readers=true, single_fragment_buffer=false)");
testlog.info("run_mutation_source_tests(evict_readers=true, single_fragment_buffer=false)");
run_mutation_source_tests(make_populate(true, false));
BOOST_TEST_MESSAGE("run_mutation_source_tests(evict_readers=true, single_fragment_buffer=true)");
testlog.info("run_mutation_source_tests(evict_readers=true, single_fragment_buffer=true)");
run_mutation_source_tests(make_populate(true, true));
return make_ready_future<>();
@@ -2516,7 +2516,7 @@ SEASTAR_THREAD_TEST_CASE(test_multishard_combining_reader_next_partition) {
return dht::ring_position_tri_compare(*schema, a, b) < 0;
});
BOOST_TEST_MESSAGE("Start test");
testlog.info("Start test");
auto assertions = assert_that(std::move(reader));
for (int i = 0; i < partition_count; ++i) {
@@ -2717,7 +2717,7 @@ SEASTAR_THREAD_TEST_CASE(test_multishard_streaming_reader) {
const auto min_size = std::min(reference_muts.size(), tested_muts.size());
for (size_t i = 0; i < min_size; ++i) {
BOOST_TEST_MESSAGE(format("Comparing mutation {:d}/{:d}", i, min_size - 1));
testlog.trace("Comparing mutation {:d}/{:d}", i, min_size - 1);
assert_that(tested_muts[i]).is_equal_to(reference_muts[i]);
}

11
test/boost/mutation_test.cc
View File

@@ -58,6 +58,7 @@
#include "service/storage_proxy.hh"
#include "test/lib/random_utils.hh"
#include "test/lib/simple_schema.hh"
#include "test/lib/log.hh"
#include "types/map.hh"
#include "types/list.hh"
#include "types/set.hh"
@@ -683,11 +684,11 @@ SEASTAR_TEST_CASE(test_cell_ordering) {
auto assert_order = [] (atomic_cell_view first, atomic_cell_view second) {
if (compare_atomic_cell_for_merge(first, second) >= 0) {
BOOST_TEST_MESSAGE(format("Expected {} < {}", first, second));
testlog.trace("Expected {} < {}", first, second);
abort();
}
if (compare_atomic_cell_for_merge(second, first) <= 0) {
BOOST_TEST_MESSAGE(format("Expected {} < {}", second, first));
testlog.trace("Expected {} < {}", second, first);
abort();
}
};
@@ -1259,7 +1260,7 @@ SEASTAR_TEST_CASE(test_query_digest) {
check_digests_equal(compacted(m1), m2);
check_digests_equal(m1, compacted(m2));
} else {
BOOST_TEST_MESSAGE("If not equal, they should become so after applying diffs mutually");
testlog.info("If not equal, they should become so after applying diffs mutually");
mutation_application_stats app_stats;
schema_ptr s = m1.schema();
@@ -1428,14 +1429,14 @@ SEASTAR_THREAD_TEST_CASE(test_row_marker_expiry) {
can_gc_fn never_gc = [] (tombstone) { return false; };
auto must_be_alive = [&] (row_marker mark, gc_clock::time_point t) {
BOOST_TEST_MESSAGE(format("must_be_alive({}, {})", mark, t));
testlog.trace("must_be_alive({}, {})", mark, t);
BOOST_REQUIRE(mark.is_live(tombstone(), t));
BOOST_REQUIRE(mark.is_missing() || !mark.is_dead(t));
BOOST_REQUIRE(mark.compact_and_expire(tombstone(), t, never_gc, gc_clock::time_point()));
};
auto must_be_dead = [&] (row_marker mark, gc_clock::time_point t) {
BOOST_TEST_MESSAGE(format("must_be_dead({}, {})", mark, t));
testlog.trace("must_be_dead({}, {})", mark, t);
BOOST_REQUIRE(!mark.is_live(tombstone(), t));
BOOST_REQUIRE(mark.is_missing() || mark.is_dead(t));
BOOST_REQUIRE(!mark.compact_and_expire(tombstone(), t, never_gc, gc_clock::time_point()));

5
test/boost/mvcc_test.cc
View File

@@ -37,6 +37,7 @@
#include "test/lib/simple_schema.hh"
#include "test/lib/mutation_source_test.hh"
#include "test/lib/failure_injecting_allocation_strategy.hh"
#include "test/lib/log.hh"
#include "test/boost/range_tombstone_list_assertions.hh"
#include "real_dirty_memory_accounter.hh"
@@ -349,7 +350,7 @@ SEASTAR_TEST_CASE(test_apply_to_incomplete) {
auto ck1 = table.make_ckey(1);
auto ck2 = table.make_ckey(2);
BOOST_TEST_MESSAGE("Check that insert falling into discontinuous range is dropped");
testlog.info("Check that insert falling into discontinuous range is dropped");
{
auto e = ms.make_evictable(mutation_partition::make_incomplete(s));
auto m = new_mutation();
@@ -358,7 +359,7 @@ SEASTAR_TEST_CASE(test_apply_to_incomplete) {
assert_that(table.schema(), e.squashed()).is_equal_to(mutation_partition::make_incomplete(s));
}
BOOST_TEST_MESSAGE("Check that continuity is a union");
testlog.info("Check that continuity is a union");
{
auto m1 = mutation_with_row(ck2);
auto e = ms.make_evictable(m1.partition());

3
test/boost/partitioner_test.cc
View File

@@ -32,6 +32,7 @@
#include "repair/range_split.hh"
#include "test/lib/simple_schema.hh"
#include "test/lib/log.hh"
#include "test/boost/total_order_check.hh"
template <typename... Args>
@@ -133,7 +134,7 @@ SEASTAR_THREAD_TEST_CASE(test_ring_position_ordering) {
keys[2]._token = keys[3]._token = keys[4]._token;
std::sort(keys.begin() + 2, keys.begin() + 5, dht::ring_position_less_comparator(*table.schema()));
BOOST_TEST_MESSAGE(format("Keys: {}", keys));
testlog.info("Keys: {}", keys);
auto positions = boost::copy_range<std::vector<dht::ring_position>>(keys);
auto ext_positions = boost::copy_range<std::vector<dht::ring_position_ext>>(keys);

5
test/boost/range_tombstone_list_test.cc
View File

@@ -28,6 +28,7 @@
#include "schema_builder.hh"
#include "range_tombstone_list.hh"
#include "test/boost/range_tombstone_list_assertions.hh"
#include "test/lib/log.hh"
static thread_local schema_ptr s = schema_builder("ks", "cf")
.with_column("pk", int32_type, column_kind::partition_key)
@@ -869,7 +870,7 @@ BOOST_AUTO_TEST_CASE(test_accumulator) {
auto ts1 = 1;
auto ts2 = 2;
BOOST_TEST_MESSAGE("Forward");
testlog.info("Forward");
auto acc = range_tombstone_accumulator(*s, false);
acc.apply(rtie(0, 4, ts1));
BOOST_REQUIRE_EQUAL(acc.tombstone_for_row(key({ 0 })), tombstone(ts1, gc_now));
@@ -890,7 +891,7 @@ BOOST_AUTO_TEST_CASE(test_accumulator) {
BOOST_REQUIRE_EQUAL(acc.tombstone_for_row(key({ 14 })), tombstone());
BOOST_REQUIRE_EQUAL(acc.tombstone_for_row(key({ 15 })), tombstone());
BOOST_TEST_MESSAGE("Reversed");
testlog.info("Reversed");
acc = range_tombstone_accumulator(*s, true);
BOOST_REQUIRE_EQUAL(acc.tombstone_for_row(key({ 15 })), tombstone());

7
test/boost/reusable_buffer_test.cc
View File

@@ -27,12 +27,13 @@
#include <boost/range/algorithm/copy.hpp>
#include "test/lib/random_utils.hh"
#include "test/lib/log.hh"
BOOST_AUTO_TEST_CASE(test_get_linearized_view) {
utils::reusable_buffer buffer;
auto test = [&buffer] (size_t n) {
BOOST_TEST_MESSAGE("Testing buffer size " << n);
testlog.info("Testing buffer size {}", n);
auto original = tests::random::get_bytes(n);
bytes_ostream bo;
@@ -76,8 +77,8 @@ BOOST_AUTO_TEST_CASE(test_make_buffer) {
utils::reusable_buffer buffer;
auto test = [&buffer] (size_t maximum, size_t actual) {
BOOST_TEST_MESSAGE("Testing maximum buffer size " << maximum << ", actual: " << actual);
testlog.info("Testing maximum buffer size {}, actual: {} ", maximum, actual);
bytes original;
auto make_buffer_fn = [&] (bytes_mutable_view view) {
original = tests::random::get_bytes(actual);

11
test/boost/row_cache_test.cc
View File

@@ -38,11 +38,10 @@
#include "memtable.hh"
#include "partition_slice_builder.hh"
#include "test/lib/memtable_snapshot_source.hh"
#include "test/lib/log.hh"
using namespace std::chrono_literals;
static seastar::logger test_log("test");
static schema_ptr make_schema() {
return schema_builder("ks", "cf")
.with_column("pk", bytes_type, column_kind::partition_key)
@@ -1036,7 +1035,7 @@ SEASTAR_TEST_CASE(test_update) {
cache_tracker tracker;
row_cache cache(s, snapshot_source_from_snapshot(cache_mt->as_data_source()), tracker, is_continuous::yes);
BOOST_TEST_MESSAGE("Check cache miss with populate");
testlog.info("Check cache miss with populate");
int partition_count = 1000;
@@ -1070,7 +1069,7 @@ SEASTAR_TEST_CASE(test_update) {
std::copy(keys_not_in_cache.begin(), keys_not_in_cache.end(), std::back_inserter(keys_in_cache));
keys_not_in_cache.clear();
BOOST_TEST_MESSAGE("Check cache miss with drop");
testlog.info("Check cache miss with drop");
auto mt2 = make_lw_shared<memtable>(s);
@@ -1088,7 +1087,7 @@ SEASTAR_TEST_CASE(test_update) {
verify_does_not_have(cache, key);
}
BOOST_TEST_MESSAGE("Check cache hit with merge");
testlog.info("Check cache hit with merge");
auto mt3 = make_lw_shared<memtable>(s);
@@ -2753,7 +2752,7 @@ SEASTAR_TEST_CASE(test_no_misses_when_read_is_repeated) {
for (auto n_ranges : {1, 2, 4}) {
auto ranges = gen.make_random_ranges(n_ranges);
BOOST_TEST_MESSAGE(format("Reading {{}}", ranges));
testlog.info("Reading {{}}", ranges);
populate_range(cache, pr, ranges);
check_continuous(cache, pr, ranges);

3
test/boost/schema_change_test.cc
View File

@@ -37,6 +37,7 @@
#include "db/config.hh"
#include "test/lib/tmpdir.hh"
#include "test/lib/exception_utils.hh"
#include "test/lib/log.hh"
SEASTAR_TEST_CASE(test_new_schema_with_no_structural_change_is_propagated) {
return do_with_cql_env([](cql_test_env& e) {
@@ -113,7 +114,7 @@ SEASTAR_TEST_CASE(test_tombstones_are_ignored_in_version_calculation) {
auto old_node_version = e.db().local().get_version();
{
BOOST_TEST_MESSAGE("Applying a no-op tombstone to v1 column definition");
testlog.info("Applying a no-op tombstone to v1 column definition");
auto s = db::schema_tables::columns();
auto pkey = partition_key::from_singular(*s, table_schema->ks_name());
mutation m(s, pkey);

32
test/boost/sstable_datafile_test.cc
View File

@@ -3697,7 +3697,7 @@ SEASTAR_TEST_CASE(test_repeated_tombstone_skipping) {
auto ck1 = table.make_ckey(1);
auto ck2 = table.make_ckey((1 + i) / 2);
auto ck3 = table.make_ckey(i);
BOOST_TEST_MESSAGE(format("checking {} {}", ck2, ck3));
testlog.info("checking {} {}", ck2, ck3);
auto slice = partition_slice_builder(*table.schema())
.with_range(query::clustering_range::make_singular(ck1))
.with_range(query::clustering_range::make_singular(ck2))
@@ -4666,7 +4666,7 @@ SEASTAR_TEST_CASE(sstable_scrub_test) {
std::vector<mutation_fragment> scrubbed_fragments;
auto sst = sst_gen();
BOOST_TEST_MESSAGE(fmt::format("Writing sstable {}", sst->get_filename()));
testlog.info("Writing sstable {}", sst->get_filename());
{
auto& partitioner = dht::global_partitioner();
@@ -4697,7 +4697,7 @@ SEASTAR_TEST_CASE(sstable_scrub_test) {
auto pkey = partition_key::from_deeply_exploded(*schema, { local_keys.at(pk) });
auto dkey = partitioner.decorate_key(*schema, pkey);
BOOST_TEST_MESSAGE(fmt::format("Writing partition {}", pkey.with_schema(*schema)));
testlog.trace("Writing partition {}", pkey.with_schema(*schema));
if (write_to_scrubbed) {
scrubbed_fragments.emplace_back(partition_start(dkey, {}));
@@ -4708,7 +4708,7 @@ SEASTAR_TEST_CASE(sstable_scrub_test) {
{
auto sr = make_static_row();
BOOST_TEST_MESSAGE(fmt::format("Writing row {}", sr.position()));
testlog.trace("Writing row {}", sr.position());
if (write_to_scrubbed) {
scrubbed_fragments.emplace_back(static_row(*schema, sr));
@@ -4721,7 +4721,7 @@ SEASTAR_TEST_CASE(sstable_scrub_test) {
for (unsigned i = 0; i < rows_count; ++i) {
auto cr = make_clustering_row(i);
BOOST_TEST_MESSAGE(fmt::format("Writing row {}", cr.position()));
testlog.trace("Writing row {}", cr.position());
if (write_to_scrubbed) {
scrubbed_fragments.emplace_back(clustering_row(*schema, cr));
@@ -4732,13 +4732,13 @@ SEASTAR_TEST_CASE(sstable_scrub_test) {
// write row twice
if (i == (rows_count / 2)) {
auto bad_cr = make_clustering_row(i - 2);
BOOST_TEST_MESSAGE(fmt::format("Writing out-of-order row {}", bad_cr.position()));
testlog.trace("Writing out-of-order row {}", bad_cr.position());
corrupt_fragments.emplace_back(clustering_row(*schema, bad_cr));
writer.consume(std::move(bad_cr));
}
}
BOOST_TEST_MESSAGE("Writing partition_end");
testlog.trace("Writing partition_end");
if (write_to_scrubbed) {
scrubbed_fragments.emplace_back(partition_end{});
@@ -4751,12 +4751,12 @@ SEASTAR_TEST_CASE(sstable_scrub_test) {
write_partition(0, false);
write_partition(2, true);
BOOST_TEST_MESSAGE("Writing done");
testlog.info("Writing done");
writer.consume_end_of_stream();
}
sst->load().get();
BOOST_TEST_MESSAGE(fmt::format("Loaded sstable {}", sst->get_filename()));
testlog.info("Loaded sstable {}", sst->get_filename());
auto cfg = column_family_test_config();
cfg.datadir = tmp.path().string();
@@ -4776,18 +4776,18 @@ SEASTAR_TEST_CASE(sstable_scrub_test) {
auto verify_fragments = [&] (sstables::shared_sstable sst, const std::vector<mutation_fragment>& mfs) {
auto r = assert_that(sst->as_mutation_source().make_reader(schema));
for (const auto& mf : mfs) {
BOOST_TEST_MESSAGE(fmt::format("Expecting {}", mutation_fragment::printer(*schema, mf)));
testlog.trace("Expecting {}", mutation_fragment::printer(*schema, mf));
r.produces(*schema, mf);
}
r.produces_end_of_stream();
};
BOOST_TEST_MESSAGE("Verifying written data...");
testlog.info("Verifying written data...");
// Make sure we wrote what we though we wrote.
verify_fragments(sst, corrupt_fragments);
BOOST_TEST_MESSAGE("Scrub with --skip-corrupted=false");
testlog.info("Scrub with --skip-corrupted=false");
// We expect the scrub with skip_corrupted=false to stop on the first invalid fragment.
compaction_manager.perform_sstable_scrub(table.get(), false).get();
@@ -4795,7 +4795,7 @@ SEASTAR_TEST_CASE(sstable_scrub_test) {
BOOST_REQUIRE(table->candidates_for_compaction().size() == 1);
verify_fragments(sst, corrupt_fragments);
BOOST_TEST_MESSAGE("Scrub with --skip-corrupted=true");
testlog.info("Scrub with --skip-corrupted=true");
// We expect the scrub with skip_corrupted=true to get rid of all invalid data.
compaction_manager.perform_sstable_scrub(table.get(), true).get();
@@ -4886,7 +4886,7 @@ SEASTAR_THREAD_TEST_CASE(sstable_scrub_reader_test) {
auto r = assert_that(make_scrubbing_reader(make_flat_mutation_reader_from_fragments(schema, std::move(corrupt_fragments)), true));
for (const auto& mf : scrubbed_fragments) {
BOOST_TEST_MESSAGE(fmt::format("Expecting {}", mutation_fragment::printer(*schema, mf)));
testlog.info("Expecting {}", mutation_fragment::printer(*schema, mf));
r.produces(*schema, mf);
}
r.produces_end_of_stream();
@@ -5072,11 +5072,11 @@ SEASTAR_TEST_CASE(sstable_run_based_compaction_test) {
do_replace(old_sstables, new_sstables);
observer = old_sstables.front()->add_on_closed_handler([&] (sstable& sst) {
BOOST_TEST_MESSAGE(sprint("Closing sstable of generation %d", sst.generation()));
testlog.info("Closing sstable of generation {}", sst.generation());
closed_sstables_tracker++;
});
BOOST_TEST_MESSAGE(sprint("Removing sstable of generation %d, refcnt: %d", old_sstables.front()->generation(), old_sstables.front().use_count()));
testlog.info("Removing sstable of generation {}, refcnt: {}", old_sstables.front()->generation(), old_sstables.front().use_count());
};
auto do_compaction = [&] (size_t expected_input, size_t expected_output) -> std::vector<shared_sstable> {

17
test/boost/sstable_mutation_test.cc
View File

@@ -45,6 +45,7 @@
#include "test/lib/make_random_string.hh"
#include "test/lib/data_model.hh"
#include "test/lib/random_utils.hh"
#include "test/lib/log.hh"
using namespace sstables;
using namespace std::chrono_literals;
@@ -1440,19 +1441,19 @@ SEASTAR_TEST_CASE(test_key_count_estimation) {
shared_sstable sst = make_sstable(env, s, dir.path().string(), muts, test_sstables_manager.configure_writer(), version);
auto max_est = sst->get_estimated_key_count();
BOOST_TEST_MESSAGE(format("count = {}", count));
BOOST_TEST_MESSAGE(format("est = {}", max_est));
testlog.trace("count = {}", count);
testlog.trace("est = {}", max_est);
{
auto est = sst->estimated_keys_for_range(dht::token_range::make_open_ended_both_sides());
BOOST_TEST_MESSAGE(format("est([-inf; +inf]) = {}", est));
testlog.trace("est([-inf; +inf]) = {}", est);
BOOST_REQUIRE_EQUAL(est, sst->get_estimated_key_count());
}
for (int size : {1, 64, 256, 512, 1024, 4096, count}) {
auto r = dht::token_range::make(pks[0].token(), pks[size - 1].token());
auto est = sst->estimated_keys_for_range(r);
BOOST_TEST_MESSAGE(format("est([0; {}] = {}", size - 1, est));
testlog.trace("est([0; {}] = {}", size - 1, est);
BOOST_REQUIRE_GE(est, size);
BOOST_REQUIRE_LE(est, max_est);
}
@@ -1462,7 +1463,7 @@ SEASTAR_TEST_CASE(test_key_count_estimation) {
auto upper = std::min(count - 1, lower + size - 1);
auto r = dht::token_range::make(pks[lower].token(), pks[upper].token());
auto est = sst->estimated_keys_for_range(r);
BOOST_TEST_MESSAGE(format("est([{}; {}]) = {}", lower, upper, est));
testlog.trace("est([{}; {}]) = {}", lower, upper, est);
BOOST_REQUIRE_GE(est, upper - lower + 1);
BOOST_REQUIRE_LE(est, max_est);
}
@@ -1470,14 +1471,14 @@ SEASTAR_TEST_CASE(test_key_count_estimation) {
{
auto r = dht::token_range::make(all_pks[0].token(), all_pks[0].token());
auto est = sst->estimated_keys_for_range(r);
BOOST_TEST_MESSAGE(format("est(non-overlapping to the left) = {}", est));
testlog.trace("est(non-overlapping to the left) = {}", est);
BOOST_REQUIRE_EQUAL(est, 0);
}
{
auto r = dht::token_range::make(all_pks[all_pks.size() - 1].token(), all_pks[all_pks.size() - 1].token());
auto est = sst->estimated_keys_for_range(r);
BOOST_TEST_MESSAGE(format("est(non-overlapping to the right) = {}", est));
testlog.trace("est(non-overlapping to the right) = {}", est);
BOOST_REQUIRE_EQUAL(est, 0);
}
}
@@ -1561,7 +1562,7 @@ SEASTAR_THREAD_TEST_CASE(test_large_index_pages_do_not_cause_large_allocations)
auto large_allocs_after = memory::stats().large_allocations();
auto duration = std::chrono::steady_clock::now() - t0;
BOOST_TEST_MESSAGE(format("Read took {:d} us", duration / 1us));
testlog.trace("Read took {:d} us", duration / 1us);
assert_that(actual).is_equal_to(expected);
BOOST_REQUIRE_EQUAL(large_allocs_after - large_allocs_before, 0);

3
test/boost/total_order_check.hh
View File

@@ -25,6 +25,7 @@
#include <boost/test/unit_test.hpp>
#include <seastar/util/variant_utils.hh>
#include <variant>
#include "test/lib/log.hh"
template<typename Comparator, typename... T>
class total_order_check {
@@ -42,7 +43,7 @@ private:
for (const element& right_e : right) {
seastar::visit(left_e, [&] (auto&& a) {
seastar::visit(right_e, [&] (auto&& b) {
BOOST_TEST_MESSAGE(format("cmp({}, {}) == {:d}", a, b, order));
testlog.trace("cmp({}, {}) == {:d}", a, b, order);
auto r = _cmp(a, b);
auto actual = this->sgn(r);
if (actual != order) {

33
test/lib/flat_mutation_reader_assertions.hh
View File

@@ -26,6 +26,7 @@
#include "flat_mutation_reader.hh"
#include "mutation_assertions.hh"
#include "schema.hh"
#include "test/lib/log.hh"
// Intended to be called in a seastar thread
class flat_reader_assertions {
@@ -53,7 +54,7 @@ public:
flat_reader_assertions& produces_partition_start(const dht::decorated_key& dk,
std::optional<tombstone> tomb = std::nullopt) {
BOOST_TEST_MESSAGE(format("Expecting partition start with key {}", dk));
testlog.trace("Expecting partition start with key {}", dk);
auto mfopt = read_next();
if (!mfopt) {
BOOST_FAIL(format("Expected: partition start with key {}, got end of stream", dk));
@@ -72,7 +73,7 @@ public:
}
flat_reader_assertions& produces_static_row() {
BOOST_TEST_MESSAGE(format("Expecting static row"));
testlog.trace("Expecting static row");
auto mfopt = read_next();
if (!mfopt) {
BOOST_FAIL("Expected static row, got end of stream");
@@ -84,7 +85,7 @@ public:
}
flat_reader_assertions& produces_row_with_key(const clustering_key& ck, std::optional<api::timestamp_type> active_range_tombstone = std::nullopt) {
BOOST_TEST_MESSAGE(format("Expect {}", ck));
testlog.trace("Expect {}", ck);
auto mfopt = read_next();
if (!mfopt) {
BOOST_FAIL(format("Expected row with key {}, but got end of stream", ck));
@@ -108,7 +109,7 @@ public:
if (!range.overlaps(*_reader.schema(), next->as_range_tombstone().position(), next->as_range_tombstone().end_position())) {
break;
}
BOOST_TEST_MESSAGE(format("Received range tombstone: {}", mutation_fragment::printer(*_reader.schema(), *next)));
testlog.trace("Received range tombstone: {}", mutation_fragment::printer(*_reader.schema(), *next));
range = position_range(position_in_partition(next->position()), range.end());
_tombstones.apply(*_reader.schema(), _reader(db::no_timeout).get0()->as_range_tombstone());
} else if (next->is_clustering_row() && next->as_clustering_row().empty()) {
@@ -118,7 +119,7 @@ public:
// There is no difference between an empty row and a row that doesn't exist.
// While readers that emit spurious empty rows may be wasteful, it is not
// incorrect to do so, so let's ignore them.
BOOST_TEST_MESSAGE(format("Received empty clustered row: {}", mutation_fragment::printer(*_reader.schema(), *next)));
testlog.trace("Received empty clustered row: {}", mutation_fragment::printer(*_reader.schema(), *next));
range = position_range(position_in_partition(next->position()), range.end());
_reader(db::no_timeout).get();
} else {
@@ -140,7 +141,7 @@ public:
};
flat_reader_assertions& produces_static_row(const std::vector<expected_column>& columns) {
BOOST_TEST_MESSAGE(format("Expecting static row"));
testlog.trace("Expecting static row");
auto mfopt = read_next();
if (!mfopt) {
BOOST_FAIL("Expected static row, got end of stream");
@@ -170,7 +171,7 @@ public:
}
flat_reader_assertions& produces_row(const clustering_key& ck, const std::vector<expected_column>& columns) {
BOOST_TEST_MESSAGE(format("Expect {}", ck));
testlog.trace("Expect {}", ck);
auto mfopt = read_next();
if (!mfopt) {
BOOST_FAIL(format("Expected row with key {}, but got end of stream", ck));
@@ -209,7 +210,7 @@ public:
flat_reader_assertions& produces_row(const clustering_key& ck,
const std::vector<column_id>& column_ids,
const std::vector<assert_function>& column_assert) {
BOOST_TEST_MESSAGE(format("Expect {}", ck));
testlog.trace("Expect {}", ck);
auto mfopt = read_next();
if (!mfopt) {
BOOST_FAIL(format("Expected row with key {}, but got end of stream", ck));
@@ -238,7 +239,7 @@ public:
// If ck_ranges is passed, verifies only that information relevant for ck_ranges matches.
flat_reader_assertions& produces_range_tombstone(const range_tombstone& rt, const query::clustering_row_ranges& ck_ranges = {}) {
BOOST_TEST_MESSAGE(format("Expect {}", rt));
testlog.trace("Expect {}", rt);
auto mfo = read_next();
if (!mfo) {
BOOST_FAIL(format("Expected range tombstone {}, but got end of stream", rt));
@@ -273,7 +274,7 @@ public:
}
flat_reader_assertions& produces_partition_end() {
BOOST_TEST_MESSAGE("Expecting partition end");
testlog.trace("Expecting partition end");
auto mfopt = read_next();
if (!mfopt) {
BOOST_FAIL(format("Expected partition end but got end of stream"));
@@ -300,7 +301,7 @@ public:
}
flat_reader_assertions& produces_end_of_stream() {
BOOST_TEST_MESSAGE("Expecting end of stream");
testlog.trace("Expecting end of stream");
auto mfopt = read_next();
if (bool(mfopt)) {
BOOST_FAIL(format("Expected end of stream, got {}", mutation_fragment::printer(*_reader.schema(), *mfopt)));
@@ -364,7 +365,7 @@ public:
}
flat_reader_assertions& produces_eos_or_empty_mutation() {
BOOST_TEST_MESSAGE("Expecting eos or empty mutation");
testlog.trace("Expecting eos or empty mutation");
auto mo = read_mutation_from_flat_mutation_reader(_reader, db::no_timeout).get0();
if (mo) {
if (!mo->partition().empty()) {
@@ -412,26 +413,26 @@ public:
}
flat_reader_assertions& fast_forward_to(const dht::partition_range& pr) {
BOOST_TEST_MESSAGE(format("Fast forward to partition range: {}", pr));
testlog.trace("Fast forward to partition range: {}", pr);
_pr = pr;
_reader.fast_forward_to(_pr, db::no_timeout).get();
return *this;
}
flat_reader_assertions& next_partition() {
BOOST_TEST_MESSAGE("Skip to next partition");
testlog.trace("Skip to next partition");
_reader.next_partition();
return *this;
}
flat_reader_assertions& fast_forward_to(position_range pr) {
BOOST_TEST_MESSAGE(format("Fast forward to clustering range: {}", pr));
testlog.trace("Fast forward to clustering range: {}", pr);
_reader.fast_forward_to(std::move(pr), db::no_timeout).get();
return *this;
}
flat_reader_assertions& fast_forward_to(const clustering_key& ck1, const clustering_key& ck2) {
BOOST_TEST_MESSAGE(format("Fast forward to clustering range: [{}, {})", ck1, ck2));
testlog.trace("Fast forward to clustering range: [{}, {})", ck1, ck2);
return fast_forward_to(position_range{
position_in_partition(position_in_partition::clustering_row_tag_t(), ck1),
position_in_partition(position_in_partition::clustering_row_tag_t(), ck2)

23
test/lib/log.cc Normal file
View File

@@ -0,0 +1,23 @@
/*
* Copyright (C) 2020 ScyllaDB
*/
/*
* This file is part of Scylla.
*
* Scylla is free software: you can redistribute it and/or modify
* it under the terms of the GNU Affero General Public License as published by
* the Free Software Foundation, either version 3 of the License, or
* (at your option) any later version.
*
* Scylla is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License
* along with Scylla. If not, see <http://www.gnu.org/licenses/>.
*/
#include "test/lib/log.hh"
seastar::logger testlog("testlog");

30
test/lib/log.hh Normal file
View File

@@ -0,0 +1,30 @@
/*
* Copyright (C) 2020 ScyllaDB
*/
/*
* This file is part of Scylla.
*
* Scylla is free software: you can redistribute it and/or modify
* it under the terms of the GNU Affero General Public License as published by
* the Free Software Foundation, either version 3 of the License, or
* (at your option) any later version.
*
* Scylla is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License
* along with Scylla. If not, see <http://www.gnu.org/licenses/>.
*/
#pragma once
#include <seastar/util/log.hh>
// A test log to use in all unit tests, including boost unit
// tests. Built-in boost logging log levels do not allow to filter
// out unimportant messages, which then clutter xunit-format XML
// output, so are not used for anything profuse.
extern seastar::logger testlog;

57
test/lib/mutation_source_test.cc
View File

@@ -34,6 +34,7 @@
#include "cql3/cql3_type.hh"
#include "test/lib/make_random_string.hh"
#include "test/lib/data_model.hh"
#include "test/lib/log.hh"
#include <boost/algorithm/string/join.hpp>
#include "types/user.hh"
#include "types/map.hh"
@@ -83,7 +84,7 @@ public:
}
static void test_slicing_and_fast_forwarding(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
simple_schema s;
@@ -170,10 +171,10 @@ static void test_slicing_and_fast_forwarding(populate_fn_ex populate) {
? query::clustering_range::make_singular(s.make_ckey(start))
: query::clustering_range::make({s.make_ckey(start)}, {s.make_ckey(start + range_size), false});
BOOST_TEST_MESSAGE(format("Clustering key range {}", range));
testlog.info("Clustering key range {}", range);
auto test_common = [&] (const query::partition_slice& slice) {
BOOST_TEST_MESSAGE("Read whole partitions at once");
testlog.info("Read whole partitions at once");
auto pranges_walker = partition_range_walker(pranges);
auto mr = ms.make_reader(s.schema(), no_reader_permit(), pranges_walker.initial_range(), slice,
default_priority_class(), nullptr, streamed_mutation::forwarding::no, fwd_mr);
@@ -199,7 +200,7 @@ static void test_slicing_and_fast_forwarding(populate_fn_ex populate) {
}
actual.produces_end_of_stream();
BOOST_TEST_MESSAGE("Read partitions with fast-forwarding to each individual row");
testlog.info("Read partitions with fast-forwarding to each individual row");
pranges_walker = partition_range_walker(pranges);
mr = ms.make_reader(s.schema(), no_reader_permit(), pranges_walker.initial_range(), slice,
default_priority_class(), nullptr, streamed_mutation::forwarding::yes, fwd_mr);
@@ -229,20 +230,20 @@ static void test_slicing_and_fast_forwarding(populate_fn_ex populate) {
actual.produces_end_of_stream();
};
BOOST_TEST_MESSAGE("Single-range slice");
testlog.info("Single-range slice");
auto slice = partition_slice_builder(*s.schema())
.with_range(range)
.build();
test_common(slice);
BOOST_TEST_MESSAGE("Test monotonic positions");
testlog.info("Test monotonic positions");
auto mr = ms.make_reader(s.schema(), no_reader_permit(), query::full_partition_range, slice,
default_priority_class(), nullptr, streamed_mutation::forwarding::no, fwd_mr);
assert_that(std::move(mr)).has_monotonic_positions();
if (range_size != 1) {
BOOST_TEST_MESSAGE("Read partitions fast-forwarded to the range of interest");
testlog.info("Read partitions fast-forwarded to the range of interest");
auto pranges_walker = partition_range_walker(pranges);
mr = ms.make_reader(s.schema(), no_reader_permit(), pranges_walker.initial_range(), slice,
default_priority_class(), nullptr, streamed_mutation::forwarding::yes, fwd_mr);
@@ -277,12 +278,12 @@ static void test_slicing_and_fast_forwarding(populate_fn_ex populate) {
actual.produces_end_of_stream();
}
BOOST_TEST_MESSAGE("Slice with not clustering ranges");
testlog.info("Slice with not clustering ranges");
slice = partition_slice_builder(*s.schema())
.with_ranges({})
.build();
BOOST_TEST_MESSAGE("Read partitions with just static rows");
testlog.info("Read partitions with just static rows");
auto pranges_walker = partition_range_walker(pranges);
mr = ms.make_reader(s.schema(), no_reader_permit(), pranges_walker.initial_range(), slice,
default_priority_class(), nullptr, streamed_mutation::forwarding::no, fwd_mr);
@@ -299,7 +300,7 @@ static void test_slicing_and_fast_forwarding(populate_fn_ex populate) {
actual.produces_end_of_stream();
if (range_size != 1) {
BOOST_TEST_MESSAGE("Slice with single-row ranges");
testlog.info("Slice with single-row ranges");
std::vector<query::clustering_range> ranges;
for (auto i = start; i < start + range_size; i++) {
ranges.emplace_back(query::clustering_range::make_singular(s.make_ckey(i)));
@@ -310,7 +311,7 @@ static void test_slicing_and_fast_forwarding(populate_fn_ex populate) {
test_common(slice);
BOOST_TEST_MESSAGE("Test monotonic positions");
testlog.info("Test monotonic positions");
auto mr = ms.make_reader(s.schema(), no_reader_permit(), query::full_partition_range, slice,
default_priority_class(), nullptr, streamed_mutation::forwarding::no, fwd_mr);
assert_that(std::move(mr)).has_monotonic_positions();
@@ -360,7 +361,7 @@ static void test_slicing_and_fast_forwarding(populate_fn_ex populate) {
}
static void test_streamed_mutation_forwarding_is_consistent_with_slicing(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
// Generates few random mutations and row slices and verifies that using
// fast_forward_to() over the slices gives the same mutations as using those
@@ -378,7 +379,7 @@ static void test_streamed_mutation_forwarding_is_consistent_with_slicing(populat
.with_ranges(ranges)
.build();
BOOST_TEST_MESSAGE(format("ranges: {}", ranges));
testlog.info("ranges: {}", ranges);
mutation_source ms = populate(m.schema(), {m}, gc_clock::now());
@@ -431,7 +432,7 @@ static void test_streamed_mutation_forwarding_is_consistent_with_slicing(populat
fwd_reader.consume(consumer(m.schema(), builder), db::no_timeout).get0();
BOOST_REQUIRE(bool(builder));
for (auto&& range : ranges) {
BOOST_TEST_MESSAGE(format("fwd {}", range));
testlog.trace("fwd {}", range);
fwd_reader.fast_forward_to(position_range(range), db::no_timeout).get();
fwd_reader.consume(consumer(m.schema(), builder), db::no_timeout).get0();
}
@@ -445,7 +446,7 @@ static void test_streamed_mutation_forwarding_is_consistent_with_slicing(populat
}
static void test_streamed_mutation_forwarding_guarantees(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
simple_schema table;
schema_ptr s = table.schema();
@@ -472,7 +473,7 @@ static void test_streamed_mutation_forwarding_guarantees(populate_fn_ex populate
mutation_source ms = populate(s, std::vector<mutation>({m}), gc_clock::now());
auto new_stream = [&ms, s, &m] () -> flat_reader_assertions {
BOOST_TEST_MESSAGE("Creating new streamed_mutation");
testlog.info("Creating new streamed_mutation");
auto res = assert_that(ms.make_reader(s,
no_reader_permit(),
query::full_partition_range,
@@ -489,7 +490,7 @@ static void test_streamed_mutation_forwarding_guarantees(populate_fn_ex populate
for (; start < end; ++start) {
if (!contains_key(start)) {
BOOST_TEST_MESSAGE(format("skip {:d}", start));
testlog.trace("skip {:d}", start);
continue;
}
sm.produces_row_with_key(keys[start]);
@@ -578,7 +579,7 @@ static void test_streamed_mutation_forwarding_guarantees(populate_fn_ex populate
// Reproduces https://github.com/scylladb/scylla/issues/2733
static void test_fast_forwarding_across_partitions_to_empty_range(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
simple_schema table;
schema_ptr s = table.schema();
@@ -652,7 +653,7 @@ static void test_fast_forwarding_across_partitions_to_empty_range(populate_fn_ex
}
static void test_streamed_mutation_slicing_returns_only_relevant_tombstones(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
simple_schema table;
schema_ptr s = table.schema();
@@ -743,7 +744,7 @@ static void test_streamed_mutation_slicing_returns_only_relevant_tombstones(popu
}
static void test_streamed_mutation_forwarding_across_range_tombstones(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
simple_schema table;
schema_ptr s = table.schema();
@@ -834,7 +835,7 @@ static void test_streamed_mutation_forwarding_across_range_tombstones(populate_f
}
static void test_range_queries(populate_fn_ex populate) {
BOOST_TEST_MESSAGE("Testing range queries");
testlog.info("Testing range queries");
auto s = schema_builder("ks", "cf")
.with_column("key", bytes_type, column_kind::partition_key)
@@ -869,7 +870,7 @@ static void test_range_queries(populate_fn_ex populate) {
auto ds = populate(s, partitions, gc_clock::now());
auto test_slice = [&] (dht::partition_range r) {
BOOST_TEST_MESSAGE(format("Testing range {}", r));
testlog.info("Testing range {}", r);
assert_that(ds.make_reader(s, no_reader_permit(), r))
.produces(slice(partitions, r))
.produces_end_of_stream();
@@ -966,7 +967,7 @@ static void test_range_queries(populate_fn_ex populate) {
}
void test_all_data_is_read_back(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
const auto query_time = gc_clock::now();
@@ -979,7 +980,7 @@ void test_all_data_is_read_back(populate_fn_ex populate) {
}
void test_mutation_reader_fragments_have_monotonic_positions(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
for_each_mutation([] (const mutation& m) {
auto rd = flat_mutation_reader_from_mutations({m});
@@ -988,7 +989,7 @@ void test_mutation_reader_fragments_have_monotonic_positions(populate_fn_ex popu
}
static void test_date_tiered_clustering_slicing(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
simple_schema ss;
@@ -1028,7 +1029,7 @@ static void test_date_tiered_clustering_slicing(populate_fn_ex populate) {
}
static void test_clustering_slices(populate_fn_ex populate) {
BOOST_TEST_MESSAGE(__PRETTY_FUNCTION__);
testlog.info(__PRETTY_FUNCTION__);
auto s = schema_builder("ks", "cf")
.with_column("key", bytes_type, column_kind::partition_key)
.with_column("c1", int32_type, column_kind::clustering_key)
@@ -2184,13 +2185,13 @@ void for_each_schema_change(std::function<void(schema_ptr, const std::vector<mut
auto test_mutated_schemas = [&] {
auto& [ base_change_log, base_schema, base_mutations ] = base;
for (auto&& [ mutated_change_log, mutated_schema, mutated_mutations ] : schemas) {
BOOST_TEST_MESSAGE(format("\nSchema change from:\n\n{}\n\nto:\n\n{}\n", base_change_log, mutated_change_log));
testlog.info("\nSchema change from:\n\n{}\n\nto:\n\n{}\n", base_change_log, mutated_change_log);
fn(base_schema, base_mutations, mutated_schema, mutated_mutations);
}
for (auto i = 2u; i < schemas.size(); i++) {
auto& [ base_change_log, base_schema, base_mutations ] = schemas[i - 1];
auto& [ mutated_change_log, mutated_schema, mutated_mutations ] = schemas[i];
BOOST_TEST_MESSAGE(format("\nSchema change from:\n\n{}\n\nto:\n\n{}\n", base_change_log, mutated_change_log));
testlog.info("\nSchema change from:\n\n{}\n\nto:\n\n{}\n", base_change_log, mutated_change_log);
fn(base_schema, base_mutations, mutated_schema, mutated_mutations);
}
schemas.clear();