Assert failure in ringbuffer_consumed in C API 2.0.3

(Moving over from forums/sdks/sdks)

I’m using the C API 2.0.3 in a loaded system talking to single none clustered Couchbase (1.8), we’re occasionally getting crashes within the API. like the one below. There can be a few different flavours of the crash but most are similar. Also the application multi threaded and is waiting for responses to implement a synchronous interface. As of yet I haven’t got a canned test case for this. Also I don’t think that any of the recent chanages since 2.0.3 are releated to this. Any suggestions for further debugging ?. See below for details on the backtrace.

(gdb) where
#0 0x00f69410 in __kernel_vsyscall ()
#1 0x00385df0 in raise () from /lib/libc.so.6
#2 0x00387701 in abort () from /lib/libc.so.6
#3 0x082a586e in ringbuffer_consumed (buffer=0xb3eb9944, nb=82) at src/ringbuffer.c:263
#4 0x082a5b8e in lcb_purge_single_server (server=0xb3eb98e0, error=LCB_ETIMEDOUT) at src/server.c:330
#5 0x082a827b in lcb_server_timeout_handler (sock=-1, which=1, arg=0xb3eb98e0) at src/timeout.c:38
#6 0x082b2a40 in event_process_active (base=0xae6eeaa0) at event.c:385
#7 0x082b2c95 in event_base_loop (base=0xae6eeaa0, flags=0) at event.c:525
#8 0x082b2329 in lcb_io_run_event_loop (iops=0x0) at plugins/io/libevent/plugin-libevent.c:320
#9 0x082a8bdc in lcb_wait (instance=0xb21571b0) at src/wait.c:60
#10 0x082a7307 in lcb_synchandler_return (instance=0xb21571b0, retcode=LCB_SUCCESS) at src/synchandler.c:263
#11 0x082a05a2 in lcb_arithmetic (instance=0xb21571b0, command_cookie=0xb36572a8, num=1, items=0x673a278) at src/arithmetic.c:40

Or with the local variables

#0 0x00f69410 in __kernel_vsyscall ()
No symbol table info available.
#1 0x00385df0 in raise () from /lib/libc.so.6
No symbol table info available.
#2 0x00387701 in abort () from /lib/libc.so.6
No symbol table info available.
#3 0x082a586e in ringbuffer_consumed (buffer=0xb3eb9944, nb=82) at src/ringbuffer.c:263
n = 0
#4 0x082a5b8e in lcb_purge_single_server (server=0xb3eb98e0, error=LCB_ETIMEDOUT) at src/server.c:330
allocated = 0
headersize = 0
nkey = 0
resp = {get = {version = 4389470, v = {v0 = {key = 0xb3879400, nkey = 2909062600, bytes = 0x82b4a19, nbytes = 341, flags = 1,
cas = 464891039690260729, datatype = 129 ‘\201’}}}, store = {version = 4389470, v = {v0 = {key = 0xb3879400,
nkey = 2909062600, cas = 1464720902681}}}, remove = {version = 4389470, v = {v0 = {key = 0xb3879400,
nkey = 2909062600, cas = 1464720902681}}}, touch = {version = 4389470, v = {v0 = {key = 0xb3879400, nkey = 2909062600,
cas = 1464720902681}}}, unlock = {version = 4389470, v = {v0 = {key = 0xb3879400, nkey = 2909062600}}}, arithmetic = {
version = 4389470, v = {v0 = {key = 0xb3879400, nkey = 2909062600, value = 1464720902681, cas = 1069446856705}}},
observe = {version = 4389470, v = {v0 = {key = 0xb3879400, nkey = 2909062600, cas = 1464720902681,
status = LCB_OBSERVE_PERSISTED, from_master = 249, ttp = 108240880, ttr = 1409}}}, stats = {version = 4389470, v = {
v0 = {server_endpoint = 0xb3879400 “”, key = 0xad64c5c8, nkey = 137054745, bytes = 0x155, nbytes = 1}}}, versions = {
version = 4389470, v = {v0 = {server_endpoint = 0xb3879400 “”, vstring = 0xad64c5c8 “”, nvstring = 137054745}}},
verbosity = {version = 4389470, v = {v0 = {server_endpoint = 0xb3879400 “”}}}, flush = {version = 4389470, v = {v0 = {
server_endpoint = 0xb3879400 “”}}}}
req = {request = {magic = 128 ‘\200’, opcode = 33 ‘!’, keylen = 1280, extlen = 0 ‘\000’, datatype = 0 ‘\000’, vbucket = 0,
bodylen = 973078528, opaque = 0, cas = 0}, bytes = “\200!\000\005\000\000\000\000\000\000\000:”, ‘\000’ }
ct = {start = 1371816089629588000, cookie = 0xb36572a8, replica = 0, vbucket = 0}
nr = 0
packet = 0xb3e05921 "\200!"
packetsize = 82
keyptr = 0x0
root = 0xb21571b0
rest = {root = 0xb1c4d610 “\240\002@\264\240\002@\264\b\326ı\b\326ı\001\001”,
read_head = 0xb1c4d610 “\240\002@\264\240\002@\264\b\326ı\b\326ı\001\001”,
write_head = 0xb1c4d610 “\240\002@\264\240\002@\264\b\326ı\b\326ı\001\001”, size = 1024, nbytes = 0}
stream = 0xb3eb991c
cookies = 0xb3eb9958
mirror = 0xb3eb9944
send_size = 0
stream_size = 75
now = 1371816092129971000
should_switch_to_backup_node = 0
#5 0x082a827b in lcb_server_timeout_handler (sock=-1, which=1, arg=0xb3eb98e0) at src/timeout.c:38
server = 0xb3eb98e0
#6 0x082b2a40 in event_process_active (base=0xae6eeaa0) at event.c:385
ev = 0xb21bf808
activeq = 0xb4ee5d80
i = 6
ncalls = 0
#7 0x082b2c95 in event_base_loop (base=0xae6eeaa0, flags=0) at event.c:525
evsel = 0x84d7ef8
evbase = 0xb2af2608
tv = {tv_sec = 2, tv_usec = 499999}
tv_p = 0x673a0e0
res = 0
done = 0
#8 0x082b2329 in lcb_io_run_event_loop (iops=0x0) at plugins/io/libevent/plugin-libevent.c:320
No locals.
#9 0x082a8bdc in lcb_wait (instance=0xb21571b0) at src/wait.c:60
idx = 1
#10 0x082a7307 in lcb_synchandler_return (instance=0xb21571b0, retcode=LCB_SUCCESS) at src/synchandler.c:263
cookie = {cookie = 0x0, callbacks = {get = 0x82a0214 <_get_callback>, store = 0x82a03c0 <_storage_callback>,
arithmetic = 0x82a0314 <_arithmetic_callback>, observe = 0x82a2828 ,
remove = 0x82a046c <_remove_callback>, stat = 0x82a27c0 ,
version = 0x82a27c8 , touch = 0x82a0464 <_touch_callback>, flush = 0x82a052c <_flush_callback>,
error = 0x82a0158 <_error_callback>, http_complete = 0x82a2808 ,
http_data = 0x82a2810 , unlock = 0x82a2818 ,
configuration = 0x82a2820 , verbosity = 0x82a27d0 },
retcode = LCB_SUCCESS}
#11 0x082a05a2 in lcb_arithmetic (instance=0xb21571b0, command_cookie=0xb36572a8, num=1, items=0x673a278) at src/arithmetic.c:40
ii = 1

Some of the other track traces:

#0 0x00a74410 in __kernel_vsyscall ()
#1 0x00385df0 in raise () from /lib/libc.so.6
#2 0x00387701 in abort () from /lib/libc.so.6
#3 0x082a586e in ringbuffer_consumed (buffer=0xa3b4844, nb=82) at src/ringbuffer.c:263
#4 0x082a5b8e in lcb_purge_single_server (server=0xa3b47e0, error=LCB_ETIMEDOUT) at src/server.c:330
#5 0x082a827b in lcb_server_timeout_handler (sock=-1, which=1, arg=0xa3b47e0) at src/timeout.c:38
#6 0x082b2a40 in event_process_active (base=0xa68a070) at event.c:385
#7 0x082b2c95 in event_base_loop (base=0xa68a070, flags=0) at event.c:525
#8 0x082b2329 in lcb_io_run_event_loop (iops=0x0) at plugins/io/libevent/plugin-libevent.c:320
#9 0x082a8bdc in lcb_wait (instance=0xa1711d0) at src/wait.c:60
#10 0x082a7307 in lcb_synchandler_return (instance=0xa1711d0, retcode=LCB_SUCCESS) at src/synchandler.c:263
#11 0x082a05a2 in lcb_arithmetic (instance=0xa1711d0, command_cookie=0xb275a988, num=1, items=0x1551078) at src/arithmetic.c:40

#0 0x0097a410 in __kernel_vsyscall ()
#1 0x00385df0 in raise () from /lib/libc.so.6
#2 0x00387701 in abort () from /lib/libc.so.6
#3 0x082a586e in ringbuffer_consumed (buffer=0xb0b19074, nb=82) at src/ringbuffer.c:263
#4 0x082a5b8e in lcb_purge_single_server (server=0xb0b19010, error=LCB_ETIMEDOUT) at src/server.c:330
#5 0x082a827b in lcb_server_timeout_handler (sock=-1, which=1, arg=0xb0b19010) at src/timeout.c:38
#6 0x082b2a40 in event_process_active (base=0xb3202af8) at event.c:385
#7 0x082b2c95 in event_base_loop (base=0xb3202af8, flags=0) at event.c:525
#8 0x082b2329 in lcb_io_run_event_loop (iops=0x0) at plugins/io/libevent/plugin-libevent.c:320
#9 0x082a8bdc in lcb_wait (instance=0xb1ba9f88) at src/wait.c:60
#10 0x082a7307 in lcb_synchandler_return (instance=0xb1ba9f88, retcode=LCB_SUCCESS) at src/synchandler.c:263
#11 0x082a0be1 in lcb_single_get (instance=0xb1ba9f88, command_cookie=0xae98fff8, item=0xadb82848) at src/get.c:209

#0 0x00b4042b in strlen () from /lib/libc.so.6
#1 0x00b0fd2e in vfprintf () from /lib/libc.so.6
#2 0x00b30514 in vsnprintf () from /lib/libc.so.6
#3 0x00b15fe5 in snprintf () from /lib/libc.so.6
#4 0x082a33f5 in try_to_connect (instance=0xb4cec030) at src/instance.c:99
#5 0x082a2d69 in lcb_switch_to_backup_node (instance=0xb4cec030, error=LCB_CONNECT_ERROR, reason=0x4d85c00 “Connection failed: Connection refused”) at src/instance.c:833
#6 0x082a3e84 in lcb_instance_connerr (instance=0xb4cec030, err=LCB_CONNECT_ERROR, errinfo=0x4d85c00 “Connection failed: Connection refused”) at src/instance.c:853
#7 0x082a322e in lcb_instance_connect_handler (sock=133, which=4, arg=0xb4cec030) at src/instance.c:1096
#8 0x082b2568 in event_process_active (base=0xb4ccfa00) at event.c:385
#9 0x082b27bd in event_base_loop (base=0xb4ccfa00, flags=0) at event.c:525
#10 0x082b1e51 in lcb_io_run_event_loop (iops=0x4d) at plugins/io/libevent/plugin-libevent.c:320
#11 0x082a8704 in lcb_wait (instance=0xb4cec030) at src/wait.c:60

Can you upgrade to 2.0.6 and check once again? There was issues like this fixed recently

Ok tried moving the application over to 2.0.6. I still get the same type of backtrace:

(gdb) bt
#0 0x00466410 in __kernel_vsyscall ()
#1 0x006b5df0 in raise () from /lib/libc.so.6
#2 0x006b7701 in abort () from /lib/libc.so.6
#3 0x082a4fba in ringbuffer_consumed (buffer=0xb5e03854, nb=82) at src/ringbuffer.c:263
#4 0x082a52da in lcb_purge_single_server (server=0xb5e037f0, error=LCB_ETIMEDOUT) at src/server.c:331
#5 0x082a7a3b in lcb_server_timeout_handler (sock=-1, which=1, arg=0xb5e037f0) at src/timeout.c:38
#6 0x00967188 in event_base_loop () from /usr/lib/libevent-1.4.so.2
#7 0x00291086 in lcb_io_run_event_loop (iops=0x0) at plugins/io/libevent/plugin-libevent.c:320
#8 0x082a83a4 in lcb_wait (instance=0xb4005118) at src/wait.c:67
#9 0x082a6ac7 in lcb_synchandler_return (instance=0xb4005118, retcode=LCB_SUCCESS) at src/synchandler.c:263
#10 0x0829f7fa in lcb_arithmetic (instance=0xb4005118, command_cookie=0xb55faf10, num=1, items=0x42d1278) at src/arithmetic.c:40

I’m going to work through the code some more to see if I can understand what’s happening, in the meanwhild any pointers appreciated.

The issue has been fixed in this patch: http://review.couchbase.org/29344