Crush when log level is trace

[tzach]

Running scylla with log level trace fail

./build/release/scylla -c 4 --commitlog-directory ~/cdata/ --data-file-directories ~/cdata/ --default-log-level=trace
....
DEBUG   [shard 2] lsa - Unregistering region, id=49
DEBUG   [shard 2] lsa - Unregistering region, id=89
DEBUG   [shard 2] lsa - Unregistering region, id=40
DEBUGDEBUG     [shard 3] lsa - Unregistering region, id=20
 [shard 1] lsa - Unregistering region, id=19
TRACE   [shard 1] lsa - Releasing segment 0x60300058b000
DEBUG   [shard 2] lsa - Unregistering region, id=18
TRACE   [shard 2] lsa - Releasing segment 0x6020005ce000
DEBUG   [shard 0] lsa - Unregistering region, id=0
TRACE   [shard 0] lsa - Releasing segment 0x6000005d7000

Running with trace level info works fine

[tgrabiec]

Could it be related to #126 ?

[slivne]

not able to reproduce with head

commit 57d41e2
Author: Tomasz Grabiec tgrabiec@cloudius-systems.com
Date: Tue Sep 1 19:00:29 2015 +0200

tests: Don't run lsa_async_eviction_test on very large batch size

Since commit 870e9e5729fcbdef334312272e2cc610d54be583 eviction no
longer happens during allocation from a region and batch size of 30000
became too large to handle. 3000 is low enough and that test case was
 left.

[slivne]

Ok was able to reproduce if scylla is booted in a non clean directory ... datadir has info

to reproduce

rm -Rf tmp/*; build/release/scylla --datadir `pwd`/tmp --commitlog-directory `pwd`/tmp --smp 4 --default-log-level trace

ctrl+c

now run

build/release/scylla --datadir `pwd`/tmp --commitlog-directory `pwd`/tmp --smp 4 --default-log-level trace

running with gdb and catch thro, after a few make_directory exceptions

we get

TRACE   [shard 0] storage_proxy - query system.local cmd=read_command{cf_id=7ad54392-bcdd-35a6-8417-4e047860b377, slice={regular_cols=[15], static_cols=[], rows=[(-inf, +inf)], options=0}, limit=2147483647, timestamp=1441146304}, ranges==={97 05 87 36 72 a6 2b cb , pk{6c6f63616c}}, id=8
Catchpoint 1 (exception thrown), 0x0000003c1405f05d in __cxa_throw () from /lib64/libstdc++.so.6
(gdb) where
#0  0x0000003c1405f05d in __cxa_throw () from /lib64/libstdc++.so.6
#1  0x00000000007fd2ce in read_simple_bytes (n=<optimized out>, v=...) at ./types.hh:921
#2  read_collection_value (in=..., sf=..., sf@entry=...) at types.cc:1213
#3  0x00000000008021b1 in set_type_impl::deserialize (this=0x60000027de00, in=..., sf=...) at types.cc:1744
#4  0x0000000000a4ec23 in deserialize_value (sf=..., v=..., this=0x60000027de00) at ./types.hh:435
#5  query::result_set_builder::deserialize (this=this@entry=0x600000a8d940, row=..., is_static=is_static@entry=false) at query-result-set.cc:156
#6  0x0000000000a4f411 in query::result_set_builder::accept_new_row (this=this@entry=0x600000a8d940, static_row=..., row=...) at query-result-set.cc:86
#7  0x0000000000a536b1 in query::result_view::consume<query::result_set_builder&> (this=this@entry=0x600000a8d930, slice=..., visitor=...) at query-result-reader.hh:155
#8  0x0000000000a4f8f2 in query::result_set::<lambda(bytes_view)>::operator()(bytes_view) (__closure=__closure@entry=0x600000a8da30, v=...) at query-result-set.cc:168
#9  0x0000000000a50b6d in query::result_set::from_raw_result (s=..., slice=..., r=...) at query-result-set.cc:173
#10 0x0000000000a4b9cc in query::result::pretty_print (this=0x600000ab4308, s=..., slice=...) at query.cc:125
#11 0x000000000084364f in operator() (res=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x5901050>, __closure=0x600000a8dd30) at service/storage_proxy.cc:1882
#12 apply (args=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x586e520>, func=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x586e50e>)
    at /home/shlomi/urchin/seastar/core/apply.hh:34
#13 apply<service::storage_proxy::query(schema_ptr, lw_shared_ptr<query::read_command>, std::vector<range<dht::ring_position> >&&, db::consistency_level)::<lambda(foreign_ptr<lw_shared_ptr<query::result> >&&)>, foreign_ptr<lw_shared_ptr<query::result> > > (args=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x586e56d>, 
    func=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x586e559>) at /home/shlomi/urchin/seastar/core/apply.hh:42
#14 futurize<foreign_ptr<lw_shared_ptr<query::result> > >::apply<service::storage_proxy::query(schema_ptr, lw_shared_ptr<query::read_command>, std::vector<range<dht::ring_position> >&&, db::consistency_level)::<lambda(foreign_ptr<lw_shared_ptr<query::result> >&&)>, foreign_ptr<lw_shared_ptr<query::result> > >(<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x5901137>, <unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x59019f6>) (func=func@entry=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x5901137>, 
    args=args@entry=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x59019f6>) at /home/shlomi/urchin/seastar/core/future.hh:1042
#15 0x000000000086c05b in then<service::storage_proxy::query(schema_ptr, lw_shared_ptr<query::read_command>, std::vector<range<dht::ring_position> >&&, db::consistency_level)::<lambda(foreign_ptr<lw_shared_ptr<query::result> >&&)>, future<foreign_ptr<lw_shared_ptr<query::result> > > > (func=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x5a1edd5>, this=0x600000a8dd50)
    at /home/shlomi/urchin/seastar/core/future.hh:768
#16 service::storage_proxy::query(lw_shared_ptr<schema const>, lw_shared_ptr<query::read_command>, std::vector<range<dht::ring_position>, std::allocator<range<dht::ring_position> > >&&, db::consistency_level) (
    this=0x600000087880, s=..., cmd=..., partition_ranges=partition_ranges@entry=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x55c23ea, DIE 0x5a21aac>, cl=cl@entry=db::consistency_level::ONE)
    at service/storage_proxy.cc:1884
#17 0x00000000007bd1c3 in cql3::statements::select_statement::execute_internal (this=0x6000007370b0, proxy=..., state=..., options=...) at cql3/statements/select_statement.cc:255
#18 0x00000000008a35bc in operator() (opts=..., __closure=0x600000a8e1d0) at cql3/query_processor.cc:311
#19 do_with<cql3::query_options, cql3::query_processor::execute_internal(const string_view&, const std::initializer_list<boost::any>&)::<lambda(cql3::query_options&)> > (
    f=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x5d351b7, DIE 0x5f52ce5>, rvalue=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x5d351b7, DIE 0x5f52db6>)
    at /home/shlomi/urchin/seastar/core/do_with.hh:55
#20 cql3::query_processor::execute_internal (this=<optimized out>, query_string=..., values=...) at cql3/query_processor.cc:311
#21 0x00000000008f4601 in execute_cql<basic_sstring<char, unsigned int, 15u> > (cf=<error reading variable: access outside bounds of object referenced via synthetic pointer>, 
    text=<error reading variable: access outside bounds of object referenced via synthetic pointer>, this=0x600000044870) at db/query_context.hh:28
#22 db::execute_cql<char const* const&, basic_sstring<char, unsigned int, 15u> >(sstring, <unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x6ca0191, DIE 0x6edf847>, const char * const&) (text=...)
    at db/query_context.hh:51
#23 0x00000000008fee25 in db::system_keyspace::get_saved_tokens () at db/system_keyspace.cc:770
#24 0x0000000000b366ac in service::storage_service::join_token_ring (this=0x60000008d700, delay=5000) at service/storage_service.cc:286
#25 0x0000000000b3a26d in service::storage_service::<lambda()>::operator()(void) const (__closure=__closure@entry=0x6000002807c0) at service/storage_service.cc:948
#26 0x0000000000b3a845 in apply (args=<optimized out>, func=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x9a4166e, DIE 0x9c001c7>) at /home/shlomi/urchin/seastar/core/apply.hh:34
#27 apply<service::storage_service::init_server(int)::<lambda()> > (args=<optimized out>, func=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x9a4166e, DIE 0x9c00204>)
    at /home/shlomi/urchin/seastar/core/apply.hh:42
#28 apply<service::storage_service::init_server(int)::<lambda()> > (args=<optimized out>, func=<unknown type in /home/shlomi/urchin/build/release/scylla, CU 0x9a4166e, DIE 0x9c00244>)
    at /home/shlomi/urchin/seastar/core/future.hh:1061
#29 operator() (__closure=<optimized out>) at /home/shlomi/urchin/seastar/core/thread.hh:203
#30 std::_Function_handler<void(), seastar::async(Func&&, Args&& ...)::<lambda(seastar::async(Func&&, Args&& ...)::work&)> [with Func = service::storage_service::init_server(int)::<lambda()>; Args = {}]::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /usr/include/c++/4.9.2/functional:2039
#31 0x000000000041b94a in operator() (this=0x6000000d8108) at /usr/include/c++/4.9.2/functional:2439
#32 seastar::thread_context::main (this=0x6000000d8100) at core/thread.cc:100
#33 0x00000000004d9802 in seastar::thread_context::s_main (lo=<optimized out>, hi=<optimized out>) at core/thread.cc:94
---Type <return> to continue, or q <return> to quit---
#34 0x0000003c0d048000 in ?? () from /lib64/libc.so.6
#35 0x0000000000000000 in ?? ()

which probably triggered a shutdown

this issue happens even without any cassandra stress client connected and sending traffic - and it seems to be indeed related to the previous issue #126 in printing the query_result

#10 0x0000000000a4b9cc in query::result::pretty_print (this=0x600000ab4308, s=..., slice=...) at query.cc:125

[avikivity]

Fixed by deccb0f