Sergey Avseyev

Thanks for opening this issue on my behalf after going through the stack trace. My bad, I should've done this in the first place. The crash was seen during one of the qe tests testing eventing rebalance with multiple kv nodes. The issue is very inconsistent, not easily reproducible. I ran the same test few times after it was reported, it passed successfully. All I can do to reproduce this would be to keep running the test until it fails in one of the runs.

Given that it's happening, do you have a mechanism of building/running with the thread sanitizer Suraj Naik or Jeelan Poola? That would more likely catch this and other issues more consistently and earlier.

Maybe not much of thread sanitizer, but rather address sanitizer from clang for instance. This is how libcouchbase should be build then cmake -DCMAKE_C_COMPILER=clang -DCMAKE_CXX_COMPILER=clang++ -DLCB_USE_ASAN=1 . && make -j8. I've tried to reproduce the issue, but without any luck yet.

The stack trace says that the problem happens, when we try to apply config attached to NMV response. And for some reason we cannot destroy current config.

How many libcouchbase instances are operating in this test? How many eventing worker threads? Is it possible that the worker thread IO related to libcouchbase instance might be executing by other threads when the worker thread does not execute any work?

It appears that MB-37167 and MB-37197 may be related. Both are related to socket handling, but fail in different ways. It looks like we cannot (or cannot easily) use tsan owing to other dependencies that are in the way of linking.

There is a patchset available for testing that we think has a good probability of solving MB-37167. It was produced by taking the general area being used and testing in an outside program under the thread sanitizer and valgrind.

As for MB-37197, it is a bit less clear if this one will be addressed with the same patchset. We want to see if it can be observed, and may want to add some additional telemetry to STDERR log host/port and address to catch when it becomes invalid. This is not currently in the patchset.

For both, we've requested an updated run, as there are issues definitely addressed with external testing.

Sergey Avseyev We do access lcb handle from two different threads. All these lcb access are protected by mutex.

Sergey Avseyev

I made a toy build with your patch and ran it on one of our dev clusters continuously and it finally crashed. The logs are here http://qa.sc.couchbase.com/job/dev_testbed_blr3/190/artifact/logs/testrunner-19-Dec-10_23-11-31/*zip*/testrunner-19-Dec-10_23-11-31.zip

There is a mini dump in the logs in node 172.23.106.73.
The console logs for the test are here http://qa.sc.couchbase.com/job/dev_testbed_blr3/190/console

The reproduction of the issue is very inconsistent, it got reproduced once in 10 runs here http://qa.sc.couchbase.com/job/dev_testbed_blr3/ - build 182 - build 191. The reproduced test build is build 190.

The link for the toy build is http://server.jenkins.couchbase.com/view/Toys/job/toy-unix-simple/lastSuccessfulBuild/artifact/couchbase-server-enterprise-6.5.0-10841-centos7.x86_64.rpm and the link for debug info build is http://server.jenkins.couchbase.com/view/Toys/job/toy-unix-simple/lastSuccessfulBuild/artifact/couchbase-server-enterprise-debuginfo-6.5.0-10841-centos7.x86_64.rpm

Info about the test
The test has one eventing node, 1 index and query node and 3 kv node. Then an eventing handler is deployed. After the deployment is successful, two more kv nodes are added and rebalanced. This rebalance fails with "Some apps are deploying or resuming on some or all Eventing nodes". This happens as one of consumer crashes with the above stack trace. And once the consumer crashes, producer respawns it again, during respawn we set the bootstrap flag, and we fail rebalance if the consumer is bootstrapping with the above message.

Suraj Naik thank you. Could you paste stack trace from minidump here, please?

Gautham Banasandra, I saw that you did some work to build consumer standalone, would it be possible to run it with thread sanitizer?

In theory, yes mutex should protect libcouchbase from concurrent access, but we don't have an application to verify and analyze it. Libcouchbase itself does not have any locks in the library, but it might be some corruption as our IO layer not only executes user-provided operations, but also has its own internal operations scheduled. It would really help if we can run the code using sanitizers or similar tools.

This is what I've got from machine 172.23.106.73 (UPDATE: this core dump is not related for this ticket)

/opt/couchbase/bin/minidump-2-core /opt/couchbase/var/lib/couchbase/crash/3585291e-88c1-7d65-7e7eaf45-39303685.dmp > crash.core

gdb /opt/couchbase/bin/eventing-consumer crash.core

#0  0x00007f7451204207 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:55

#1  0x00007f74512058f8 in __GI_abort () at abort.c:90

#2  0x00007f7451246d27 in __libc_message (do_abort=do_abort@entry=2, 

    fmt=fmt@entry=0x7f7451358678 "*** Error in `%s': %s: 0x%s ***\n") at ../sysdeps/unix/sysv/linux/libc_fatal.c:196

#3  0x00007f745124f489 in malloc_printerr (ar_ptr=0x7f7428000020, ptr=<optimized out>, 

    str=0x7f7451358738 "double free or corruption (fasttop)", action=3) at malloc.c:5004

#4  _int_free (av=0x7f7428000020, p=<optimized out>, have_lock=0) at malloc.c:3843

#5  0x00007f74528b7871 in mcreq_wipe_packet (pipeline=pipeline@entry=0x7f742804b3f0, packet=packet@entry=0x7f742804b370)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/mc/mcreq.c:238

#6  0x00007f74528b91cd in mcreq_packet_done (pipeline=0x7f742804b3f0, pkt=pkt@entry=0x7f742804b370)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/mc/mcreq.c:780

#7  0x00007f7452923e78 in mcreq__pktflush_callback (p=0x7f742804b370, hint=65, arg=0x7f744cc5ce00)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/mc/mcreq-flush-inl.h:68

#8  0x00007f74528bcdab in netbuf_end_flush2 (mgr=mgr@entry=0x7f742804b430, nflushed=nflushed@entry=65, 

    callback=callback@entry=0x7f7452923dd0 <mcreq__pktflush_callback(void*, nb_SIZE, void*)>, lloff=lloff@entry=8, 

    arg=arg@entry=0x7f744cc5ce00) at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/netbuf/netbuf.c:684

#9  0x00007f74529285e3 in mcreq_flush_done_ex (now=<optimized out>, expected=65, nflushed=65, pl=0x7f742804b3f0)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/mc/mcreq-flush-inl.h:97

#10 on_flush_done (ctx=<optimized out>, expected=65, actual=65)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/mcserver/mcserver.cc:85

#11 0x00007f74528c244b in E_put_ex (nb=65, niov=<optimized out>, iov=0x7f744cc5ce90, ctx=0x7f74280e59f0)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/lcbio/ctx.c:538

#12 lcbio_ctx_put_ex (ctx=ctx@entry=0x7f74280e59f0, iov=iov@entry=0x7f744cc5ce90, niov=<optimized out>, nb=65)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/lcbio/ctx.c:616

#13 0x00007f7452923d79 in on_flush_ready (ctx=0x7f74280e59f0)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/mcserver/mcserver.cc:68

#14 0x00007f74528c0d32 in E_handler (sock=<optimized out>, which=<optimized out>, arg=0x7f74280e59f0)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/lcbio/ctx.c:322

#15 0x00007f74528a6872 in run_loop (io=<optimized out>, is_tick=<optimized out>)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/plugins/io/select/plugin-select.c:323

#16 0x00007f745293574e in lcb_wait (instance=0x7f74480d0060)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/libcouchbase/src/wait.cc:103

#17 0x0000000000463686 in RetryWithFixedBackoff<bool (&)(lcb_error_t), lcb_error_t (&)(lcb_st*), lcb_st*&, lcb_error_t, 0> (

    callable=@0x40a460: {lcb_error_t (lcb_st *)} 0x40a460 <lcb_wait@plt>, isRetriable=<optimized out>, 

    initial_delay_milliseconds=200, max_retry_count=5)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/features/include/retry_util.h:40

#18 0x0000000000463b4d in timer::TimerStore::Get (this=0x7f74480ef050, key=...)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing-ee/features/src/timer_store.cc:421

#19 0x0000000000468408 in timer::Iterator::GetNextTimer (this=this@entry=0x7f744cc5db60, tevent=...)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing-ee/features/src/timer_iterator.cc:52

#20 0x0000000000468bd2 in timer::Iterator::GetNext (this=this@entry=0x7f744cc5db60, tevent=...)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing-ee/features/src/timer_iterator.cc:131

#21 0x000000000042ad1b in V8Worker::RouteMessage (this=0x7f7448014870)

    at /home/couchbase/jenkins/workspace/toy-unix-simple/goproj/src/github.com/couchbase/eventing/v8_consumer/src/v8worker.cc:488

#22 0x00007f7451d89dcf in std::execute_native_thread_routine (__p=0x7f74480eb970)

    at /tmp/deploy/gcc-7.3.0/libstdc++-v3/src/c++11/thread.cc:83

#23 0x00007f74515a2dd5 in start_thread (arg=0x7f744cc61700) at pthread_create.c:307

#24 0x00007f74512cbead in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

>> I saw that you did some work to build consumer standalone, would it be possible to run it with thread sanitizer?
Sergey Avseyev From the stack trace seen above, libcouchbase SDK is crashing while doing KV ops in timers. The standalone consumer was very minimal. It only ran N1QL queries and doesn't have the ability create/execute timers.

Do those timers also involve passing control on the lcb_t between threads? Or for KV ops all of them isolated an pinned to the thread?

>> Do those timers also involve passing control on the lcb_t between threads?
No, there is no passing of control involved between threads.

>> Or for KV ops all of them isolated an pinned to the thread?
KV ops can happen from 2 different threads using the same lcb_handle but protected by a mutex. We scanned code multiple times and did not find a case where they can happen unprotected.

did the scan include sources of libcouchbase?

When you call `lcb_wait` it will actively check for data on all sockets (and open/close sockets during rebalance), not only related to command scheduled by the thread. That potentially might involve triggering the callbacks that should not be triggered in current thread.

>> did the scan include sources of libcouchbase?

No, we did not scan libcouchbase code. Only eventing code.

>> When you call `lcb_wait` it will actively check for data on all sockets (and open/close
>> sockets during rebalance), not only related to command scheduled by the thread. That
>> potentially might involve triggering the callbacks that should not be triggered in current >> thread.

We have 2 timer_stores each with it's own lcb_instance in 2 different threads. It is possible that these 2 timer_stores are using their respective lcb_instances at the same time doing their own lcb_wait()s during rebalance or any other time. Do you think this can cause any problem?

The previous multi-thread-access-with-mutex I mentioned earlier is at a single timer_store level involving a single lcb_instance.

In case when lcb instance is dedicated to the thread, then it is okay, and they are not interfere with each other. Each thread will run its own `select()` loop and should not exchange any state.

Just had call with Jeelan Poola and Suraj Naik. The stack track I've posted here earlier is not related to the actual problem. New run with the patch fails in exactly the same place, which means the problem must be in libcouchbase logic for handling configuration updates. As an action items I will provide patch with more introspection on where the config is destroyed, and how it is updated. Also I will try to create an example program which simulate this timers workload and be suitable for sanitizers under the rebalance stress.

Note since we're merging two sets of things to fix this for posterity.

1) In an isolated test under dynamic testing tools, a set of issues with construction/destruction of the sockets was found. These are legitimate issues, while not the direct cause for the observation above it appears after additional testing.
2) Removal of the field from the struct which was always implicated in the crash. We lack a way to run additional stateful memory analysis tools with the tests right now and adding instrumentation did not surface any issues in either initialization or destruction of the structure. Still, it's happening somewhere we cannot identify. We removed the field from the structure expecting the failure to move to somewhere else (since something was clearly referencing it), but instead what happens is the tests pass.

Build couchbase-server-7.0.0-1141 contains libcouchbase commit 5a9160b with commit message:
CCBC-1130: Fix leaking sockets and timers

Build couchbase-server-7.0.0-1141 contains libcouchbase commit 417e30a with commit message:
CCBC-1130: Remove usage of 'buuid' of vbucket config

I'm resolving this as incomplete, because we managed to get rid of the crash by removing code in site where crash happens. But we still don't know what might be triggering the behaviour. Please reopen the issue if more information will be gathered (such as libasan/Valgrind reports)

Build couchbase-server-6.5.1-6019 contains libcouchbase commit 5a9160b with commit message:
CCBC-1130: Fix leaking sockets and timers

Build couchbase-server-6.5.1-6019 contains libcouchbase commit 417e30a with commit message:
CCBC-1130: Remove usage of 'buuid' of vbucket config

Build couchbase-server-6.5.0-4955 contains libcouchbase commit 5a9160b with commit message:
CCBC-1130: Fix leaking sockets and timers

Build couchbase-server-6.5.0-4955 contains libcouchbase commit 417e30a with commit message:
CCBC-1130: Remove usage of 'buuid' of vbucket config

Build couchbase-server-1006.5.1-1120 contains libcouchbase commit 5a9160b with commit message:
CCBC-1130: Fix leaking sockets and timers

Build couchbase-server-1006.5.1-1120 contains libcouchbase commit 417e30a with commit message:
CCBC-1130: Remove usage of 'buuid' of vbucket config

Better fix of this issue here: https://github.com/couchbase/libcouchbase/commit/fa80a2c029854c33216e679127d630f435e0cc0f

It will be backported to release-2.10

libcouchbase 3.0.7 and 2.10.9 will have new fix