Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.0.4
    • Component/s: library
    • Security Level: Public
    • Labels:
      None
    • 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

      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:

      1. 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

      1. cbget.c
        3 kB
        TimSmith
      2. t.c
        8 kB
        TimSmith
      # Subject Project Status CR V
      For Gerrit Dashboard: &For+CCBC-62=message:CCBC-62

        Activity

        TimSmith Tim Smith (Inactive) created issue -
        Hide
        TimSmith Tim Smith (Inactive) added a comment -

        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; }
        Show
        TimSmith Tim Smith (Inactive) added a comment - 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; }
        Hide
        TimSmith Tim Smith (Inactive) added a comment -

        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

        Show
        TimSmith Tim Smith (Inactive) added a comment - 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
        Hide
        TimSmith Tim Smith (Inactive) added a comment -

        Simple cbget command to just get a single key.

        Show
        TimSmith Tim Smith (Inactive) added a comment - Simple cbget command to just get a single key.
        TimSmith Tim Smith (Inactive) made changes -
        Field Original Value New Value
        Attachment cbget.c [ 13163 ]
        Hide
        ingenthr Matt Ingenthron added a comment -

        This could be related to the issue found and fixed today.

        Show
        ingenthr Matt Ingenthron added a comment - This could be related to the issue found and fixed today.
        avsej Sergey Avseyev made changes -
        Status Open [ 1 ] In Progress [ 3 ]
        Hide
        avsej Sergey Avseyev added a comment -

        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

        Show
        avsej Sergey Avseyev added a comment - 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
        Hide
        avsej Sergey Avseyev added a comment -

        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

        Show
        avsej Sergey Avseyev added a comment - 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
        Hide
        avsej Sergey Avseyev added a comment -

        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

        Show
        avsej Sergey Avseyev added a comment - 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
        Hide
        avsej Sergey Avseyev added a comment -

        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

        Show
        avsej Sergey Avseyev added a comment - 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
        Hide
        avsej Sergey Avseyev added a comment -

        Fixed here http://review.couchbase.org/15966 and awaiting for review

        Show
        avsej Sergey Avseyev added a comment - Fixed here http://review.couchbase.org/15966 and awaiting for review
        Show
        avsej Sergey Avseyev added a comment - https://github.com/couchbase/libcouchbase/commit/3d101adff79725dcad0f6e374733f4f593e6c980
        avsej Sergey Avseyev made changes -
        Status In Progress [ 3 ] Resolved [ 5 ]
        Fix Version/s 1.0.4 [ 10327 ]
        Resolution Fixed [ 1 ]
        avsej Sergey Avseyev made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        brett19 Brett Lawson made changes -
        Workflow jira [ 16874 ] Couchbase SDK Workflow [ 43725 ]

          People

          • Assignee:
            avsej Sergey Avseyev
            Reporter:
            TimSmith Tim Smith (Inactive)
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Gerrit Reviews

              There are no open Gerrit changes