[CCBC-62] hang in libcouchbase_wait() after get timeout Created: 01/May/12  Updated: 13/Nov/12  Resolved: 15/May/12

Status: Closed
Project: Couchbase C client library libcouchbase
Component/s: library
Affects Version/s: None
Fix Version/s: 1.0.4
Security Level: Public

Type: Bug Priority: Major
Reporter: Tim Smith (Inactive) Assignee: Sergey Avseyev
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment: libcouchbase built from git://github.com/couchbase/libcouchbase.git master branch at commit 9cfda9d40a270fc3dd05018eb16a2089c83bf24a

CentOS 5.6, couchbase server 1.8.0, 2-node cluster

Attachments: File cbget.c     File t.c    

 Description   
When one node is down and dropping packets, a store op trying to write to that node times out (OK) but libcouchbase_wait doesn't return (not OK).

[root@localhost cb-crank]# gcc -g -Wall -W -I$I/include -L$I/lib t.c -lcouchbase -o t
[root@localhost cb-crank]# export LD_LIBRARY_PATH=$I/lib
[root@localhost cb-crank]# ./t
Stored: hello (6)
Got: hellow (7) = world! (7)
[root@localhost cb-crank]# ./t hellow foo
Stored: hellow (7)
Got: hellow (7) = foo (4)
[root@localhost cb-crank]# ./t xyz
Got: hellow (7) = foo (4)
Failed during store 'xyz': Operation timed out



Setup: Start two nodes of Couchbase Server. In my test, they're on 10.4.2.13 and 10.4.2.14. Client (see attached code) is being run on host 10.4.2.14.

On one node (10.4.2.13), simulate a network problem with iptables:

iptables -I INPUT 1 -p tcp --sport 1000:60000 -j DROP
iptables -I INPUT 2 -p tcp --dport 1000:60000 -j DROP

Run the sample app a few times with different keys until you hit one that needs to access the down node. As seen in the output above, the storage callback is called with a timeout error, but the libcouchbase_wait() call never returns. Attach debugger to the client and view thread stacks:

# gdb -p 21746
GNU gdb (GDB) CentOS (7.0.1-42.el5.centos)
Copyright (C) 2009 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 21746
Reading symbols from /root/code/cb-crank/t...done.
Reading symbols from /root/code/install/lib/libcouchbase.so.1...done.
Loaded symbols for /root/code/install/lib/libcouchbase.so.1
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /root/code/install/lib/libvbucket.so.1...done.
Loaded symbols for /root/code/install/lib/libvbucket.so.1
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libm.so.6
Reading symbols from /root/code/install/lib/libcouchbase_libevent.so.1...done.
Loaded symbols for /root/code/install/lib/libcouchbase_libevent.so.1
Reading symbols from /opt/couchbase/lib/libevent-2.0.so.5...(no debugging symbols found)...done.
Loaded symbols for /opt/couchbase/lib/libevent-2.0.so.5
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Loaded symbols for /lib64/libpthread.so.0

warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff822c0000
0x0000003407cd3603 in __epoll_wait_nocancel () from /lib64/libc.so.6
(gdb) where
#0 0x0000003407cd3603 in __epoll_wait_nocancel () from /lib64/libc.so.6
#1 0x00002b0211713c28 in ?? () from /opt/couchbase/lib/libevent-2.0.so.5
#2 0x00002b0211702a4c in event_base_loop () from /opt/couchbase/lib/libevent-2.0.so.5
#3 0x0000000000400d60 in main (argc=1, argv=0x7fff822027f0) at t.c:113
(gdb) thread apply all bt

Thread 1 (Thread 0x2b02114eeaf0 (LWP 21746)):
#0 0x0000003407cd3603 in __epoll_wait_nocancel () from /lib64/libc.so.6
#1 0x00002b0211713c28 in ?? () from /opt/couchbase/lib/libevent-2.0.so.5
#2 0x00002b0211702a4c in event_base_loop () from /opt/couchbase/lib/libevent-2.0.so.5
#3 0x0000000000400d60 in main (argc=1, argv=0x7fff822027f0) at t.c:113
(gdb) quit


Line t.c:113 is libcouchbase_wait().


Client compiled as:

gcc -g -Wall -W -I$I/include -L$I/lib t.c -lcouchbase -o t



 Comments   
Comment by Tim Smith (Inactive) [ 10/May/12 ]
I forgot to re-enable packets, so I was unable to log in the machine. So I made this little script to hopefully avoid that mistake. Might be handy for you. Just save it, and run:

./drop-packets 90
./drop-packets 2m
./drop-packets 1h30m


#! /usr/bin/env perl

use strict;
use warnings;

my $time = shift || '10m';
my $seconds = fromNiceTime($time);

$| = 1; # Auto-flush STDOUT

die "Usage: $0 TIME\n\n TIME looks like: 30m or 1m30s, etc.\n" unless $time;

print "Dropping for $time ($seconds seconds), in 5 seconds (Hit ^C to abort) ";
sleep(5);
print "\n";

startDroppingPackets();

sleep($seconds);

stopDroppingPackets();

exit 0;


sub fromNiceTime {
    my ($str) = @_;

    my $seconds = 0;
    if ($str =~ s/^(\d+)d//) {
        $seconds += $1 * 24 * 60 * 60;
    }
    if ($str =~ s/^(\d+)h//) {
        $seconds += $1 * 60 * 60;
    }
    if ($str =~ s/^(\d+)m//) {
        $seconds += $1 * 60;
    }
    if ($str =~ s/^(\d+)s?$//) {
        $seconds += $1;
    }

    return $seconds if $str eq '';

    return undef;
}


sub startDroppingPackets {
    print "Dropping...\n";
    execute(qw(iptables -I INPUT 1 -p tcp --sport 1000:60000 -j DROP));
    execute(qw(iptables -I INPUT 2 -p tcp --dport 1000:60000 -j DROP));
}


sub stopDroppingPackets {
    execute(qw(iptables -D INPUT 1));
    execute(qw(iptables -D INPUT 1));
    print "Stopped.\n";
}

sub execute {
    my @args = @_;

    my $rc = system(@args);
    return 1 if $rc == 0;

    warn "Failed running [@args]: Code ", ($rc >> 8), ": $!\n";
    return undef;
}
Comment by Tim Smith (Inactive) [ 10/May/12 ]
A lesser problem happens when the host is not dropping packets, but just the couchbase-server service is stopped.

In this case, there's a 2.5-sec wait after the get callback hits the error, until libcouchbase_wait() call returns. I'd expect it to return right away, because there's no more work to be done.

To reproduce, start a cluster with 2 or 3 nodes. Ensure everything's working OK. Then shut down one of the nodes:

service couchbase-server stop

Now run the client, try with a few different keys until you find one for the down server:

root@localhost cb-crank]# time ./cbget 10.4.2.14:8091 Administrator password default hello
Got: hello: 776f726c642100

real 0m0.017s
user 0m0.005s
sys 0m0.002s
[root@localhost cb-crank]# time ./cbget 10.4.2.14:8091 Administrator password default xyz
Failed during get 'xyz': 23 (Connection failure)

real 0m2.517s
user 0m0.005s
sys 0m0.001s
[root@localhost cb-crank]#

Note tha the "Failed during get" message appears immediately, and then there is a 2.5-second wait before the client exits.

Complete client code (a bit simpler than the first one) is attached as cbget.c, compiled as:

gcc -g -Wall -W -I/root/code/install/include -L/root/code/install/lib -Wl,-rpath,/root/code/install/lib cbget.c -lcouchbase -o cbget

Comment by Tim Smith (Inactive) [ 10/May/12 ]
Simple cbget command to just get a single key.
Comment by Matt Ingenthron [ 10/May/12 ]
This could be related to the issue found and fixed today.
Comment by Sergey Avseyev [ 11/May/12 ]
1. it is better not to use Administrator account to connect to cluster (default bucket should be accessible)
2. looks like your cbget.c has typo, but it depends how you are storing the key (I've used 'cbc cp' command which doesn't send zero byte for key, and therefore 'nkey[0]' should be 'strlen(key)')
3. interesting, but my ruby gem (based on libcouchbase) fails fast if some node (which should receive the key) is down
Comment by Sergey Avseyev [ 11/May/12 ]
This is because your program ignores errors in the callback, the libcouchbase call your get callback with the error immediately, I'm looking for why libcouchbase continue waiting then
Comment by Sergey Avseyev [ 11/May/12 ]
Looks like it isn't possible to get notification from libevent regarding socket closed (if address is valid), this is why we are using timeouts to check when to breakout the event loop.

You are free to use libcouchbase_wait(), the libcouchbase allows event loops, executed by user (this is how I handle it in ruby client). In this case you should build IO object and breakout event loop immediately when you received the error. Take a look at couchview.c example https://github.com/couchbase/libcouchbase/blob/master/example/couchview.c#L289
Comment by Sergey Avseyev [ 14/May/12 ]
I think I found the issue, and it is indeed bug in the libcouchbase. It has enough information to breakout event loop and release wait() function. The problem in releasing one of the internal buffers and I'm working on fix now
Comment by Sergey Avseyev [ 14/May/12 ]
Fixed here http://review.couchbase.org/15966 and awaiting for review
Comment by Sergey Avseyev [ 15/May/12 ]
https://github.com/couchbase/libcouchbase/commit/3d101adff79725dcad0f6e374733f4f593e6c980
Generated at Fri Aug 22 00:00:45 CDT 2014 using JIRA 5.2.4#845-sha1:c9f4cc41abe72fb236945343a1f485c2c844dac9.