Fix assert in SpanHolder::finish() with fibers by Avogar · Pull Request #49673 · ClickHouse/ClickHouse

Avogar · 2023-05-08T16:53:41Z

Changelog category (leave one):

Bug Fix (user-visible misbehavior in an official stable release)

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Fix assert in SpanHolder::finish() with fibers by making thread local variable fiber local.
Closes #49185
Closes #49178

robot-ch-test-poll2 · 2023-05-08T16:54:59Z

This is an automated comment for commit 900aca5 with description of existing statuses. It's updated for the latest CI running
The full report is available here
The overall status of the commit is 🔴 error

Check name	Description	Status
AST fuzzer	Runs randomly generated queries to catch program errors. The build type is optionally given in parenthesis. If it fails, ask a maintainer for help	🟢 success
Bugfix validate check	Checks that either a new test (functional or integration) or there some changed tests that fail with the binary built on master branch	🔴 error
CI running	A meta-check that indicates the running CI. Normally, it's in success or pending state. The failed status indicates some problems with the PR	🟢 success
ClickHouse build check	Builds ClickHouse in various configurations for use in further steps. You have to fix the builds that fail. Build logs often has enough information to fix the error, but you might have to reproduce the failure locally. The cmake options can be found in the build log, grepping for cmake. Use these options and follow the general build process	🟢 success
Compatibility check	Checks that clickhouse binary runs on distributions with old libc versions. If it fails, ask a maintainer for help	🟢 success
Docker image for servers	The check to build and optionally push the mentioned image to docker hub	🟢 success
Fast test	Normally this is the first check that is ran for a PR. It builds ClickHouse and runs most of stateless functional tests, omitting some. If it fails, further checks are not started until it is fixed. Look at the report to see which tests fail, then reproduce the failure locally as described here	🟢 success
Flaky tests	Checks if new added or modified tests are flaky by running them repeatedly, in parallel, with more randomization. Functional tests are run 100 times with address sanitizer, and additional randomization of thread scheduling. Integrational tests are run up to 10 times. If at least once a new test has failed, or was too long, this check will be red. We don't allow flaky tests, read the doc	🟢 success
Install packages	Checks that the built packages are installable in a clear environment	🟢 success
Integration tests	The integration tests report. In parenthesis the package type is given, and in square brackets are the optional part/total tests	🟢 success
Mergeable Check	Checks if all other necessary checks are successful	🟢 success
Performance Comparison	Measure changes in query performance. The performance test report is described in detail here. In square brackets are the optional part/total tests	🟢 success
Push to Dockerhub	The check for building and pushing the CI related docker images to docker hub	🟢 success
SQLancer	Fuzzing tests that detect logical bugs with SQLancer tool	🟢 success
Sqllogic	Run clickhouse on the sqllogic test set against sqlite and checks that all statements are passed	🟢 success
Stateful tests	Runs stateful functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc	🟢 success
Stateless tests	Runs stateless functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc	🟢 success
Stress test	Runs stateless functional tests concurrently from several clients to detect concurrency-related errors	🟢 success
Style Check	Runs a set of checks to keep the code style clean. If some of tests failed, see the related log from the report	🟢 success
Unit tests	Runs the unit tests for different release types	🟢 success
Upgrade check	Runs stress tests on server version from last release and then tries to upgrade it to the version from the PR. It checks if the new server can successfully startup without any errors, crashes or sanitizer asserts	🟢 success

qoega · 2023-05-08T17:41:14Z

Check this one as well, please

https://s3.amazonaws.com/clickhouse-test-reports/0/5629d73bdbb5d321f7cd49c8c3b0e3a39d6ab1d4/stress_test__tsan_.html

2023-05-08 18:01:35 Thread 607 "TCPHandler" received signal SIGSEGV, Segmentation fault.
2023-05-08 18:01:35 [Switching to Thread 0x7fd0cdbfe700 (LWP 2629)]
2023-05-08 18:01:35 0x0000555ed2edc77d in __tsan::ThreadContext::OnFinished() ()
2023-05-08 18:01:35 #0  0x0000555ed2edc77d in __tsan::ThreadContext::OnFinished() ()
2023-05-08 18:01:35 No symbol table info available.
2023-05-08 18:01:35 #1  0x0000555ed2e47a9c in __sanitizer::ThreadRegistry::FinishThread(unsigned int) ()
2023-05-08 18:01:35 No symbol table info available.
2023-05-08 18:01:35 #2  0x0000555ed2edc4fb in __tsan::ThreadFinish(__tsan::ThreadState*) ()
2023-05-08 18:01:35 No symbol table info available.
2023-05-08 18:01:35 #3  0x0000555ed2edcd20 in __tsan::FiberDestroy(__tsan::ThreadState*, unsigned long, __tsan::ThreadState*) ()
2023-05-08 18:01:35 No symbol table info available.
2023-05-08 18:01:35 #4  0x0000555ee366ad55 in boost::context::detail::fiber_activation_record::~fiber_activation_record (this=0x7fcf83df4b00) at ./contrib/boost/boost/context/fiber_ucontext.hpp:121
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #5  0x0000555ee366acc0 in boost::context::detail::fiber_capture_record<boost::context::fiber, FiberStack&, DB::AsyncTaskExecutor::Routine>::destroy (p=0x7fcf83df4b00) at ./contrib/boost/boost/context/fiber_ucontext.hpp:255
2023-05-08 18:01:35         salloc = {stack_size = <optimized out>, page_size = 4096, static default_stack_size = 327680}
2023-05-08 18:01:35         sctx = {size = 331776, sp = 0x7fcf83df5000}
2023-05-08 18:01:35 #6  boost::context::detail::fiber_capture_record<boost::context::fiber, FiberStack&, DB::AsyncTaskExecutor::Routine>::deallocate (this=0x7fcf83df4b00) at ./contrib/boost/boost/context/fiber_ucontext.hpp:269
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #7  0x0000555ee366a699 in boost::context::fiber::~fiber (this=0x7b4803387188) at ./contrib/boost/boost/context/fiber_ucontext.hpp:450
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #8  DB::AsyncTaskExecutor::~AsyncTaskExecutor (this=<optimized out>) at ./src/Common/AsyncTaskExecutor.h:59
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #9  0x0000555ee62014d0 in DB::ConnectionEstablisherAsync::~ConnectionEstablisherAsync (this=0x7b4803387180) at ./src/Client/ConnectionEstablisher.h:57
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #10 0x0000555ee620bf5a in DB::ConnectionEstablisherAsync::~ConnectionEstablisherAsync (this=0x7b4803387180) at ./src/Client/ConnectionEstablisher.h:57
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #11 0x0000555ee621801d in std::__1::default_delete<DB::ConnectionEstablisherAsync>::operator()[abi:v15000](DB::ConnectionEstablisherAsync*) const (this=0x7b2000f03f00, __ptr=0x7b4803387180) at ./contrib/llvm-project/libcxx/include/__memory/unique_ptr.h:48
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #12 std::__1::unique_ptr<DB::ConnectionEstablisherAsync, std::__1::default_delete<DB::ConnectionEstablisherAsync> >::reset[abi:v15000](DB::ConnectionEstablisherAsync*) (this=0x7b2000f03f00, __p=0x0) at ./contrib/llvm-project/libcxx/include/__memory/unique_ptr.h:305
2023-05-08 18:01:35         __tmp = 0x7b4803387180
2023-05-08 18:01:35 #13 std::__1::unique_ptr<DB::ConnectionEstablisherAsync, std::__1::default_delete<DB::ConnectionEstablisherAsync> >::~unique_ptr[abi:v15000]() (this=0x7b2000f03f00) at ./contrib/llvm-project/libcxx/include/__memory/unique_ptr.h:259
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #14 DB::HedgedConnectionsFactory::ReplicaStatus::~ReplicaStatus (this=0x7b2000f03f00) at ./src/Client/HedgedConnectionsFactory.h:37
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #15 std::__1::__destroy_at[abi:v15000]<DB::HedgedConnectionsFactory::ReplicaStatus, 0>(DB::HedgedConnectionsFactory::ReplicaStatus*) (__loc=0x7b2000f03f00) at ./contrib/llvm-project/libcxx/include/__memory/construct_at.h:63
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #16 std::__1::destroy_at[abi:v15000]<DB::HedgedConnectionsFactory::ReplicaStatus, 0>(DB::HedgedConnectionsFactory::ReplicaStatus*) (__loc=0x7b2000f03f00) at ./contrib/llvm-project/libcxx/include/__memory/construct_at.h:88
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #17 std::__1::allocator_traits<std::__1::allocator<DB::HedgedConnectionsFactory::ReplicaStatus> >::destroy[abi:v15000]<DB::HedgedConnectionsFactory::ReplicaStatus, void, void>(std::__1::allocator<DB::HedgedConnectionsFactory::ReplicaStatus>&, DB::HedgedConnectionsFactory::ReplicaStatus*) (__p=0x7b2000f03f00) at ./contrib/llvm-project/libcxx/include/__memory/allocator_traits.h:317
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #18 std::__1::vector<DB::HedgedConnectionsFactory::ReplicaStatus, std::__1::allocator<DB::HedgedConnectionsFactory::ReplicaStatus> >::__base_destruct_at_end[abi:v15000](DB::HedgedConnectionsFactory::ReplicaStatus*) (this=0x7b6401911380, __new_last=0x7b2000f03f00) at ./contrib/llvm-project/libcxx/include/vector:833
2023-05-08 18:01:35         __soon_to_be_end = 0x7b2000f03f00
2023-05-08 18:01:35 #19 std::__1::vector<DB::HedgedConnectionsFactory::ReplicaStatus, std::__1::allocator<DB::HedgedConnectionsFactory::ReplicaStatus> >::__clear[abi:v15000]() (this=0x7b6401911380) at ./contrib/llvm-project/libcxx/include/vector:827
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #20 std::__1::vector<DB::HedgedConnectionsFactory::ReplicaStatus, std::__1::allocator<DB::HedgedConnectionsFactory::ReplicaStatus> >::~vector[abi:v15000]() (this=0x7b6401911380) at ./contrib/llvm-project/libcxx/include/vector:436
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #21 DB::HedgedConnectionsFactory::~HedgedConnectionsFactory (this=0x7b6401911308) at ./src/Client/HedgedConnectionsFactory.cpp:54
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #22 0x0000555ee6213e46 in DB::HedgedConnections::~HedgedConnections (this=this@entry=0x7b6401911300) at ./src/Client/HedgedConnections.h:29
2023-05-08 18:01:36 No locals.
2023-05-08 18:01:36 #23 0x0000555ee6213e9a in DB::HedgedConnections::~HedgedConnections (this=0x7b6401911300) at ./src/Client/HedgedConnections.h:29
2023-05-08 18:01:36 No locals.
2023-05-08 18:01:36 #24 0x0000555ee3656825 in std::__1::default_delete<DB::IConnections>::operator()[abi:v15000](DB::IConnections*) const (this=<optimized out>, __ptr=0x7b6401911300) at ./contrib/llvm-project/libcxx/include/__memory/unique_ptr.h:48
2023-05-08 18:01:36 No locals.

Avogar · 2023-05-08T17:45:33Z

Check this one as well, please

Sure, I already saw it. Actually, it looks like a bug in tsan itself.

ThreadSanitizer: CHECK failed: tsan_interceptors_posix.cpp:1987 "((thr->slot)) != (0)" (0x0, 0x0) (tid=2629)

The same check as in #37910, but commented that it should be fixed in clang-15. @tavplubix maybe you can add something?

tavplubix · 2023-05-08T23:52:07Z

Actually, it looks like a bug in tsan itself.

I'm not sure

The same check as in #37910

The stacktrace is different, it's another issue. #37910 was related to signal handling in tsan, see google/sanitizers#1541. And now there are no signals but SIGSEGV:

2023-05-08 18:01:35 Thread 607 "TCPHandler" received signal SIGSEGV, Segmentation fault.
2023-05-08 18:01:35 [Switching to Thread 0x7fd0cdbfe700 (LWP 2629)]
2023-05-08 18:01:35 0x0000555ed2edc77d in __tsan::ThreadContext::OnFinished() ()
2023-05-08 18:01:35 #0  0x0000555ed2edc77d in __tsan::ThreadContext::OnFinished() ()
2023-05-08 18:01:35 No symbol table info available.
2023-05-08 18:01:35 #1  0x0000555ed2e47a9c in __sanitizer::ThreadRegistry::FinishThread(unsigned int) ()
2023-05-08 18:01:35 No symbol table info available.
2023-05-08 18:01:35 #2  0x0000555ed2edc4fb in __tsan::ThreadFinish(__tsan::ThreadState*) ()
2023-05-08 18:01:35 No symbol table info available.
2023-05-08 18:01:35 #3  0x0000555ed2edcd20 in __tsan::FiberDestroy(__tsan::ThreadState*, unsigned long, __tsan::ThreadState*) ()
2023-05-08 18:01:35 No symbol table info available.
2023-05-08 18:01:35 #4  0x0000555ee366ad55 in boost::context::detail::fiber_activation_record::~fiber_activation_record (this=0x7fcf83df4b00) at ./contrib/boost/boost/context/fiber_ucontext.hpp:121
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #5  0x0000555ee366acc0 in boost::context::detail::fiber_capture_record<boost::context::fiber, FiberStack&, DB::AsyncTaskExecutor::Routine>::destroy (p=0x7fcf83df4b00) at ./contrib/boost/boost/context/fiber_ucontext.hpp:255
2023-05-08 18:01:35         salloc = {stack_size = <optimized out>, page_size = 4096, static default_stack_size = 327680}
2023-05-08 18:01:35         sctx = {size = 331776, sp = 0x7fcf83df5000}
2023-05-08 18:01:35 #6  boost::context::detail::fiber_capture_record<boost::context::fiber, FiberStack&, DB::AsyncTaskExecutor::Routine>::deallocate (this=0x7fcf83df4b00) at ./contrib/boost/boost/context/fiber_ucontext.hpp:269
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #7  0x0000555ee366a699 in boost::context::fiber::~fiber (this=0x7b4803387188) at ./contrib/boost/boost/context/fiber_ucontext.hpp:450
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #8  DB::AsyncTaskExecutor::~AsyncTaskExecutor (this=<optimized out>) at ./src/Common/AsyncTaskExecutor.h:59
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #9  0x0000555ee62014d0 in DB::ConnectionEstablisherAsync::~ConnectionEstablisherAsync (this=0x7b4803387180) at ./src/Client/ConnectionEstablisher.h:57
2023-05-08 18:01:35 No locals.
2023-05-08 18:01:35 #10 0x0000555ee620bf5a in DB::ConnectionEstablisherAsync::~ConnectionEstablisherAsync (this=0x7b4803387180) at ./src/Client/ConnectionEstablisher.h:57
2023-05-08 18:01:35 No locals.
... (the remaining frames are not so interesting)

ThreadSanitizer: CHECK failed

AFAIR, this check may fail when tsan gets an unexpected synchronous signal. So this check has failed because of SIGSEGV (tsan tried to handle it but failed). Let's try to find where exactly it got segfault (we don't have line numbers in the stacktrace, but we have disasm with the instruction pointer):

   0x0000555ed2edc760 <+496>:	cmpq   $0x0,0x8(%rax)
   0x0000555ed2edc765 <+501>:	je     0x555ed2edc9ce <_ZN6__tsan13ThreadContext10OnFinishedEv+1118>
   0x0000555ed2edc76b <+507>:	mov    0x0(%r13),%rsi
   0x0000555ed2edc76f <+511>:	mov    0xa081c0(%rsi),%rbx
   0x0000555ed2edc776 <+518>:	lea    0x18(%rax),%rbp

        INode* next = after->next_;
   0x0000555ed2edc77a <+522>:	mov    (%rbx),%rdx
        n->next_ = next;
=> 0x0000555ed2edc77d <+525>:	mov    %rdx,0x18(%rax)
        n->prev_ = after;
   0x0000555ed2edc781 <+529>:	mov    %rbx,0x20(%rax)
        next->prev_ = n;
   0x0000555ed2edc785 <+533>:	mov    %rbp,0x8(%rdx)
        after->next_ = n;
   0x0000555ed2edc789 <+537>:	mov    %rbp,(%rbx)
        size_++;
   0x0000555ed2edc78c <+540>:	incq   0xa081c8(%rsi)

   0x0000555ed2edc793 <+547>:	mov    0x8(%rax),%rdx
   0x0000555ed2edc797 <+551>:	lea    -0x8(%rdx),%rax
   0x0000555ed2edc79b <+555>:	cmp    %rcx,%rdx
   0x0000555ed2edc79e <+558>:	mov    %rax,%rdx
   0x0000555ed2edc7a1 <+561>:	cmove  %r8,%rdx
   0x0000555ed2edc7a5 <+565>:	mov    %rdx,0xd8(%r15)
   0x0000555ed2edc7ac <+572>:	test   %rdx,%rdx
   0x0000555ed2edc7af <+575>:	jne    0x555ed2edc760 <_ZN6__tsan13ThreadContext10OnFinishedEv+496>

Looks like it represents this loop with IList::Push inlined. It got segfault on attempt to read (%rbx) (=> points to the next instruction), or, on attempt to dereference after here, where after is node_.prev_. Also, after = rbx = 0x7fd136abb018, looks like something on a stack.

So, seems like the list was corrupted somehow. How it could happen:

There's a bug in the list implementation in tsan
There's a race condition in tsan, so the list was accessed concurrently
ClickHouse (or boost) has corrupted the memory
Something else

1 and 2 are unlikely, so I would say it's 3 or 4. It's a bit suspicious that it involves FiberDestroy, and it provides a caller some access to tsan internals (and ability to break something), need to check it more carefully

tavplubix · 2023-05-09T12:42:11Z

=> points to the next instruction

Sorry, I was mistaken, actually it points to the faulty instruction (because it was not executed and rip was not updated). So actually it crashed on attempt to execute mov %rdx,0x18(%rax), that is n->next_ = next;, where n is trace.local_head->trace_parts, and n = rax = 0x555ee361e12f.

It's interesting that it must have executed cmpq $0x0,0x8(%rax) (or mov 0x8(%rax),%rdx) successfully to get here, so it can read from that address, but cannot write. And yes, n = rax = 0x555ee361e12f looks like an address of some executable code:

2023-05-08 18:02:34 rax            0x555ee361e12f      93866030129455
2023-05-08 18:02:34 rbp            0x555ee361e147      0x555ee361e147 <LZ4::decompress(char const*, char*, unsigned long, unsigned long, LZ4::PerformanceStatistics&)+295>

Btw, a similar address (begin_pos = 0x555ee361ecf6) can be found in stacktraces with local variables:

2023-05-08 18:01:49 Thread 818 (Thread 0x7fd0341f2700 (LWP 3198)):
2023-05-08 18:01:49 #0  0x0000555ed2e40a1a in __sanitizer::FutexWait(__sanitizer::atomic_uint32_t*, unsigned int) ()
2023-05-08 18:01:49 No symbol table info available.
2023-05-08 18:01:49 #1  0x0000555ed2e41ada in __sanitizer::Semaphore::Wait() ()
2023-05-08 18:01:49 No symbol table info available.
2023-05-08 18:01:49 #2  0x0000555ed2ec8450 in __tsan::TraceSwitchPartImpl(__tsan::ThreadState*) ()
2023-05-08 18:01:49 No symbol table info available.
2023-05-08 18:01:49 #3  0x0000555ed2ecbbd4 in __tsan::RestartUnalignedMemoryAccess(__tsan::ThreadState*, unsigned long, unsigned long, unsigned long, unsigned long) ()
2023-05-08 18:01:49 No symbol table info available.
2023-05-08 18:01:49 #4  0x0000555eea2c4cc8 in CityHash_v1_0_2::WeakHashLen32WithSeeds (s=0x7fcf57936c89 "et/?C+\"51\036", a=<optimized out>, b=3758122850392140791) at ./contrib/cityhash102/src/city.cc:176
2023-05-08 18:01:49 No locals.
2023-05-08 18:01:49 #5  CityHash_v1_0_2::CityHash128WithSeed (s=<optimized out>, len=36291, seed=...) at ./contrib/cityhash102/src/city.cc:319
2023-05-08 18:01:49         v = {first = 6215661365088335101, second = 7514665944893769875}
2023-05-08 18:01:49         w = <optimized out>
2023-05-08 18:01:49         x = 116711906202103773
2023-05-08 18:01:49         y = 3758122850392140791
2023-05-08 18:01:49         z = 11219653876939658002
2023-05-08 18:01:49         tail_done = <optimized out>
2023-05-08 18:01:49 #6  0x0000555eea2c5363 in CityHash_v1_0_2::CityHash128 (s=s@entry=0x7fcf57931f19 "\202\323\332", len=len@entry=56019) at ./contrib/cityhash102/src/city.cc:356
2023-05-08 18:01:49 No locals.
2023-05-08 18:01:49 #7  0x0000555ee35a2542 in DB::validateChecksum (data=data@entry=0x7fcf57931f19 "\202\323\332", size=size@entry=56019, expected_checksum=...) at ./src/Compression/CompressedReadBufferBase.cpp:44
2023-05-08 18:01:49         message = warning: can't find linker symbol for virtual table for `DB::WriteBufferFromOwnString' value
2023-05-08 18:01:49 warning:   found `__tsan::RestartUnalignedMemoryAccess(__tsan::ThreadState*, unsigned long, unsigned long, unsigned long, unsigned long)' instead
2023-05-08 18:01:49 {<DB::detail::StringHolder> = {value = {static __endian_factor = 1, __r_ = {<std::__1::__compressed_pair_elem<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >::__rep, 0, false>> = {__value_ = {{__l = {__data_ = 0x7fd1a4c3cee8 "\004\004`\317\036\066\356Uj\317!^\317\017", __size_ = 140528614231914, __cap_ = 140528614231914, __is_long_ = 0}, __s = {__data_ = "\350\316\303\244\321\177\000\000j\317!^\317\177\000\000j\317!^\317\177", __padding_ = 0x7fd0341e8137 "", __size_ = 0 '\000', __is_long_ = 0 '\000'}, __r = {__words = {140538389188328, 140528614231914, 140528614231914}}}}}, <std::__1::__compressed_pair_elem<std::__1::allocator<char>, 1, true>> = {<std::__1::allocator<char>> = {<std::__1::__non_trivial_if<true, std::__1::allocator<char> >> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, static npos = 18446744073709551615}}, <DB::WriteBufferFromVector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >> = {<DB::WriteBuffer> = {<DB::BufferBase> = {pos = 0x8 <error: Cannot access memory at address 0x8>, bytes = 6191946043637105668, working_buffer = {begin_pos = 0x555ee361ecf6 <LZ4::(anonymous namespace)::decompressImpl<8ul, true>(char const*, char*, unsigned long, unsigned long)+1142> "\017(\205p\377\377\377A\017\021\004$I\203\304\020I\203\307\376u\304H\213E\220H9E\270L\213m\210\017\204\302\373\377\377f\220\351&\377\377\377\350\326\321\210\357\363A\017o\f$L\215\065\211\065B\352H\213]\300\363A\017o\004\336f\017\070", end_pos = 0x555ed2ecbbd4 <__tsan::RestartUnalignedMemoryAccess(__tsan::ThreadState*, unsigned long, unsigned long, unsigned long, unsigned long)+36> "\213\023\205\322\017\210\364\004"}, internal_buffer = {begin_pos = 0x1 <error: Cannot access memory at address 0x1>, end_pos = 0x55ee361ec6300404 <error: Cannot access memory at address 0x55ee361ec6300404>}, padded = 99}, _vptr$WriteBuffer = 0x555ed2ecbbd4 <__tsan::RestartUnalignedMemoryAccess(__tsan::ThreadState*, unsigned long, unsigned long, unsigned long, unsigned long)+36>, finalized = 236}, vector = @0x0, static initial_size = 32, static size_multiplier = 2}, <No data fields>}
2023-05-08 18:01:49         calculated_checksum = <optimized out>
2023-05-08 18:01:49         difference = <optimized out>
2023-05-08 18:01:49         message_hardware_failure = <optimized out>
2023-05-08 18:01:49         flip_bit = <optimized out>
2023-05-08 18:01:49 #8  0x0000555ee35a1fe4 in DB::CompressedReadBufferBase::readCompressedData (this=<optimized out>, size_decompressed=<optimized out>, size_compressed_without_checksum=@0x7fd0341e83f8: 56019, always_copy=<optimized out>) at ./src/Compression/CompressedReadBufferBase.cpp:200
2023-05-08 18:01:49         checksum = {first = 14730044498646389939, second = 9361948234867992799}
2023-05-08 18:01:49         checksum_in = <incomplete type>
2023-05-08 18:01:49         header_size = 9 '\t'
2023-05-08 18:01:49         additional_size_at_the_end_of_buffer = <optimized out>
2023-05-08 18:01:49 #9  0x0000555ee35a4525 in DB::CompressedReadBufferFromFile::nextImpl (this=0x7b34005f70b0) at ./src/Compression/CompressedReadBufferFromFile.cpp:22

tavplubix · 2023-05-09T15:47:23Z

Btw, a similar address (begin_pos = 0x555ee361ecf6) can be found in stacktraces with local variables:

Probably it's because WriteBufferFromOwnString message; was not initialized yet at ./src/Compression/CompressedReadBufferBase.cpp:44, so it's fine.

Another interesting observation: 0xd8(%r15) looks like trace.local_head, so &trace = r15 = 0x7fd016dc07b0. However, rsp = 0x7fd0cdbf47b0, so trace is probably located on another thread's stack

Backport #49673 to 23.4: Fix assert in SpanHolder::finish() with fibers

Avogar added 3 commits May 8, 2023 16:33

Fix assert in SpanHolder::finish() with fibers

b320527

Use only needed src files

5527d43

Clean up

c961e37

robot-ch-test-poll2 added pr-bugfix Pull request with bugfix, not backported by default submodule changed At least one submodule changed in this PR. labels May 8, 2023

Avogar added pr-must-backport Pull request should be backported intentionally. Use this label with great care! v23.4-must-backport and removed pr-must-backport Pull request should be backported intentionally. Use this label with great care! labels May 8, 2023

alexey-milovidov approved these changes May 8, 2023

View reviewed changes

alexey-milovidov self-assigned this May 8, 2023

Avogar marked this pull request as draft May 9, 2023 11:24

Avogar and others added 8 commits May 9, 2023 18:56

Use own fiber local implementation

930c8c3

Update cmake

6697166

Inherit context from parent fiber

0cf6b9f

Fix indents

10e6f5b

Fix indents

a7aec49

Merge branch 'master' into fiber-local-var

289af62

Merge branch 'master' into fiber-local-var

084a696

Don't update contrib

37e4c53

robot-clickhouse removed the submodule changed At least one submodule changed in this PR. label May 12, 2023

tavplubix mentioned this pull request May 15, 2023

New system table zookeeper connection #45245

Merged

Fix build for aarch64-darwin

b23afdc

Avogar marked this pull request as ready for review May 15, 2023 15:48

robot-clickhouse-ci-2 added the submodule changed At least one submodule changed in this PR. label May 15, 2023

Avogar and others added 3 commits May 15, 2023 15:52

Better comments

78064d0

Delete unneded files

bfcaf95

Delete unneded files

900aca5

Avogar merged commit b414760 into ClickHouse:master May 16, 2023

robot-clickhouse-ci-2 mentioned this pull request May 16, 2023

Cherry pick #49673 to 23.4: Fix assert in SpanHolder::finish() with fibers #49906

Merged

robot-clickhouse-ci-2 mentioned this pull request May 16, 2023

Backport #49673 to 23.4: Fix assert in SpanHolder::finish() with fibers #49907

Merged

robot-clickhouse added a commit that referenced this pull request May 16, 2023

Backport #49673 to 23.4: Fix assert in SpanHolder::finish() with fibers

fcfb812

robot-clickhouse-ci-2 added the pr-backports-created Backport PRs are successfully created, it won't be processed by CI script anymore label May 16, 2023

Avogar added a commit that referenced this pull request May 17, 2023

Merge pull request #49907 from ClickHouse/backport/23.4/49673

268e7a1

Backport #49673 to 23.4: Fix assert in SpanHolder::finish() with fibers

This was referenced May 19, 2023

Abort in OpenTelemetry::SpanHolder::finish() #49185

Closed

Change fields destruction order in AsyncTaskExecutor #50151

Merged

tavplubix mentioned this pull request May 30, 2023

Assertion inside tsan related to HedgedConnections (possibly duplicate) #50295

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix assert in SpanHolder::finish() with fibers#49673

Fix assert in SpanHolder::finish() with fibers#49673
Avogar merged 15 commits intoClickHouse:masterfrom
Avogar:fiber-local-var

Avogar commented May 8, 2023

Uh oh!

robot-ch-test-poll2 commented May 8, 2023 •

edited by robot-ch-test-poll1

Loading

Uh oh!

qoega commented May 8, 2023 •

edited

Loading

Uh oh!

Avogar commented May 8, 2023 •

edited

Loading

Uh oh!

tavplubix commented May 8, 2023

Uh oh!

tavplubix commented May 9, 2023

Uh oh!

tavplubix commented May 9, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

Conversation

Avogar commented May 8, 2023

Changelog category (leave one):

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Uh oh!

robot-ch-test-poll2 commented May 8, 2023 • edited by robot-ch-test-poll1 Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

qoega commented May 8, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Avogar commented May 8, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tavplubix commented May 8, 2023

Uh oh!

tavplubix commented May 9, 2023

Uh oh!

tavplubix commented May 9, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

robot-ch-test-poll2 commented May 8, 2023 •

edited by robot-ch-test-poll1

Loading

qoega commented May 8, 2023 •

edited

Loading

Avogar commented May 8, 2023 •

edited

Loading