KeyDB dying via SIGABORT

[smartattack]

KeyDB has been dying with a SIGABORT sporadically every few days. This is on a CentOS 7 system using systemd. Systemd appears to be hiding the error message, but when run from a terminal the output during the crash is:

-bash-4.2$ /usr/bin/keydb-server
/etc/keydb/keydb-tty.conf keydb-server: fastlock.cpp:436: void fastlock_free(fastlock*): Assertion `(lock->m_ticket.m_active == lock->m_ticket.m_avail) || (lock->m_pidOwner == gettid() && (lock->m_ticket.m_active == lock->m_ticket.m_avail-1))' failed.

There is no logfile entry to correspond with this crash.

Configuration is as follows:

bind 127.0.0.1 10.10.5.51
protected-mode no
port 6379
tcp-backlog 8192
timeout 0
tcp-keepalive 300
daemonize yes
supervised no
pidfile /var/run/keydb/keydb-server.pid
loglevel verbose
logfile /var/log/keydb/keydb-server.log
databases 2
always-show-logo yes
save 3600 100
stop-writes-on-bgsave-error yes
rdbcompression yes
rdbchecksum yes
dbfilename dump.rdb
dir /var/lib/keydb
replica-serve-stale-data yes
replica-read-only yes
repl-diskless-sync no
repl-diskless-sync-delay 5
repl-disable-tcp-nodelay no
replica-priority 100
maxmemory 100gb
lazyfree-lazy-eviction no
lazyfree-lazy-expire no
lazyfree-lazy-server-del no
replica-lazy-flush no
appendonly no
appendfilename "appendonly.aof"
appendfsync everysec
no-appendfsync-on-rewrite no
auto-aof-rewrite-percentage 100
auto-aof-rewrite-min-size 64mb
aof-load-truncated yes
aof-use-rdb-preamble yes
lua-time-limit 5000
slowlog-log-slower-than 10000
slowlog-max-len 128
latency-monitor-threshold 0
notify-keyspace-events ""
hash-max-ziplist-entries 512
hash-max-ziplist-value 64
list-max-ziplist-size -2
list-compress-depth 0
set-max-intset-entries 512
zset-max-ziplist-entries 128
zset-max-ziplist-value 64
hll-sparse-max-bytes 3000
stream-node-max-bytes 4096
stream-node-max-entries 100
activerehashing yes
client-output-buffer-limit normal 0 0 0
client-output-buffer-limit replica 256mb 64mb 60
client-output-buffer-limit pubsub 32mb 8mb 60
hz 10
dynamic-hz yes
aof-rewrite-incremental-fsync yes
rdb-save-incremental-fsync yes
server-threads 4

[JohnSully]

Hi @smartattack

This assert wasn't setup to generate stack traces. I've update the code to ensure a proper debug report is created. Could you try updating to unstable so we can get the callstack?

If you use docker the unstable image will be updated.

[smartattack]

That did the trick - trace attached:

=== KEYDB BUG REPORT START: Cut & paste starting from here ===
19114:21314:M 03 May 2020 17:53:09.446 # === ASSERTION FAILED ===
19114:21314:M 03 May 2020 17:53:09.446 # ==> fastlock.cpp:435 '(lock->m_ticket.m_active == lock->m_ticket.m_avail) || (lock->m_pidOwner == gettid() && (lock->m_ticket.m_active == lock->m_ticket.m_avail-1))' is not true
19114:21314:M 03 May 2020 17:53:09.446 # (forcing SIGSEGV to print the bug report.)
19114:21314:M 03 May 2020 17:53:09.446 # KeyDB 0.0.0 crashed by signal: 11
19114:21314:M 03 May 2020 17:53:09.446 # Crashed running the instruction at: 0x492683
19114:21314:M 03 May 2020 17:53:09.446 # Accessing address: 0xffffffffffffffff
19114:21314:M 03 May 2020 17:53:09.446 # Failed assertion: (lock->m_ticket.m_active == lock->m_ticket.m_avail) || (lock->m_pidOwner == gettid() && (lock->m_ticket.m_active == lock->m_ticket.m_avail-1)) (fastlock.cpp:435)

------ STACK TRACE ------
EIP:
/usr/bin/keydb-server-unstable 127.0.0.1:6379(_serverAssert+0x73) [0x492683]

Backtrace:
/usr/bin/keydb-server-unstable 127.0.0.1:6379(logStackTrace(ucontext*)+0x29) [0x493bf9]
/usr/bin/keydb-server-unstable 127.0.0.1:6379(sigsegvHandler(int, siginfo_t*, void*)+0xae) [0x4942ae]
/lib64/libpthread.so.0(+0xf5f0) [0x7f4a15ee55f0]
/usr/bin/keydb-server-unstable 127.0.0.1:6379(_serverAssert+0x73) [0x492683]
/usr/bin/keydb-server-unstable 127.0.0.1:6379(fastlock_free+0x74) [0x4e2164]
/usr/bin/keydb-server-unstable 127.0.0.1:6379(freeClient(client*)+0x305) [0x456705]
/usr/bin/keydb-server-unstable 127.0.0.1:6379(handleClientsWithPendingWrites(int, int)+0x26c) [0x45c1cc]
/usr/bin/keydb-server-unstable 127.0.0.1:6379(beforeSleepLite(aeEventLoop*)+0x85) [0x443115]
/usr/bin/keydb-server-unstable 127.0.0.1:6379(aeMain+0x6b) [0x43fd3b]
/usr/bin/keydb-server-unstable 127.0.0.1:6379(workerThreadMain(void*)+0x8f) [0x44398f]
/lib64/libpthread.so.0(+0x7e65) [0x7f4a15edde65]
/lib64/libc.so.6(clone+0x6d) [0x7f4a15c0688d]

------ INFO OUTPUT ------

Server

redis_version:0.0.0
redis_git_sha1:dcd7b684
redis_git_dirty:0
redis_build_id:4893de6522606426
redis_mode:standalone
os:Linux 3.10.0-1062.1.2.el7.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:9.1.1
process_id:19114
run_id:dd803616e1f2f020bee1ceec2e986b1f753d3d0b
tcp_port:6379
uptime_in_seconds:163195
uptime_in_days:1
hz:10
configured_hz:10
lru_clock:11470085
executable:/usr/bin/keydb-server-unstable
config_file:/etc/keydb/keydb-tty.conf

Clients

connected_clients:124
client_recent_max_input_buffer:2
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
current_client_thread:1
thread_0_clients:47
thread_1_clients:49
thread_2_clients:28
thread_3_clients:0

Memory

used_memory:24334569568
used_memory_human:22.66G
used_memory_rss:44765868032
used_memory_rss_human:41.69G
used_memory_peak:25833989120
used_memory_peak_human:24.06G
used_memory_peak_perc:94.20%
used_memory_overhead:8980922452
used_memory_startup:9063520
used_memory_dataset:15353647116
used_memory_dataset_perc:63.12%
allocator_allocated:24334868784
allocator_active:44191031296
allocator_resident:44786106368
total_system_memory:270258642944
total_system_memory_human:251.70G
used_memory_lua:37888
used_memory_lua_human:37.00K
used_memory_scripts:0
used_memory_scripts_human:0B
number_of_cached_scripts:0
maxmemory:107374182400
maxmemory_human:100.00G
maxmemory_policy:noeviction
allocator_frag_ratio:1.82
allocator_frag_bytes:19856162512
allocator_rss_ratio:1.01
allocator_rss_bytes:595075072
rss_overhead_ratio:1.00
rss_overhead_bytes:-20238336
mem_fragmentation_ratio:1.84
mem_fragmentation_bytes:20431293328
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_clients_slaves:0
mem_clients_normal:6094492
mem_aof_buffer:0
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0

Persistence

loading:0
rdb_changes_since_last_save:2783007
rdb_bgsave_in_progress:0
rdb_last_save_time:1588525563
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:600
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:6158061568
aof_enabled:0
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_last_write_status:ok
aof_last_cow_size:0
module_fork_in_progress:0
module_fork_last_cow_size:0

Stats

total_connections_received:33745
total_commands_processed:8680674655
instantaneous_ops_per_sec:177192
total_net_input_bytes:1205056409857
total_net_output_bytes:60242126831
instantaneous_input_kbps:23919.39
instantaneous_output_kbps:1206.11
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:115899421
expired_stale_perc:0.00
expired_time_cap_reached_count:972
expire_cycle_cpu_milliseconds:0
evicted_keys:0
keyspace_hits:8418810182
keyspace_misses:154105837
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:1253449
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:0
active_defrag_misses:0
active_defrag_key_hits:0
active_defrag_key_misses:0
tracking_total_keys:0
tracking_total_items:0
unexpected_error_replies:0

Replication

role:master
connected_slaves:0
master_replid:48f7c713f6fb1631083317b358f38830b6ddc377
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
master_repl_meaningful_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:1048576
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

CPU

used_cpu_sys:75901.614487
used_cpu_user:75128.413677
used_cpu_sys_children:1718.635668
used_cpu_user_children:14176.985601
server_threads:4
long_lock_waits:6532

Modules

Commandstats

cmdstat_command:calls=1,usec=2269,usec_per_call=2269.00
cmdstat_ping:calls=473196,usec=590149,usec_per_call=1.25
cmdstat_get:calls=8526095622,usec=24024666468,usec_per_call=2.82
cmdstat_setex:calls=107285439,usec=621263381,usec_per_call=5.79
cmdstat_hget:calls=46820397,usec=98894687,usec_per_call=2.11

Cluster

cluster_enabled:0

Keyspace

db0:keys=113355027,expires=113355025,avg_ttl=26339476

------ CLIENT LIST OUTPUT ------
id=33732 addr=10.10.5.115:47062 fd=226 name= age=299 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33373 addr=10.10.5.112:48414 fd=97 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33590 addr=10.10.5.111:60130 fd=108 name= age=2040 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33731 addr=10.10.5.117:46324 fd=124 name= age=300 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33383 addr=10.10.5.113:35144 fd=106 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33721 addr=10.10.5.113:54136 fd=196 name= age=359 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33621 addr=10.10.5.114:38374 fd=105 name= age=1778 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33387 addr=10.10.5.115:44236 fd=102 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33495 addr=10.10.5.115:56824 fd=174 name= age=3509 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33696 addr=10.10.5.111:56806 fd=223 name= age=780 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33676 addr=10.10.5.114:36412 fd=107 name= age=966 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33610 addr=10.10.5.115:58616 fd=224 name= age=1889 idle=29 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=ping user=default
id=33694 addr=10.10.5.116:37032 fd=213 name= age=781 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33684 addr=10.10.5.117:59156 fd=139 name= age=839 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33594 addr=10.10.5.114:59896 fd=197 name= age=2017 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33713 addr=10.10.5.115:37042 fd=173 name= age=478 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33711 addr=10.10.5.117:35132 fd=157 name= age=479 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33742 addr=10.10.5.115:59086 fd=181 name= age=148 idle=28 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=ping user=default
id=33405 addr=10.10.5.113:35170 fd=158 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33750 addr=10.10.5.115:43088 fd=193 name= age=58 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=hget user=default
id=33408 addr=10.10.5.112:48438 fd=171 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33409 addr=10.10.5.112:48428 fd=131 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33718 addr=10.10.5.114:43276 fd=119 name= age=369 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33523 addr=10.10.5.117:53892 fd=95 name= age=2938 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33643 addr=10.10.5.112:42090 fd=144 name= age=1381 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33649 addr=10.10.5.116:56398 fd=185 name= age=1199 idle=29 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=ping user=default
id=33666 addr=10.10.5.116:43296 fd=175 name= age=1079 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33659 addr=10.10.5.115:55504 fd=218 name= age=1168 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=130 qbuf-free=32638 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33603 addr=10.10.5.117:35426 fd=208 name= age=1919 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33415 addr=10.10.5.116:46878 fd=137 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33661 addr=10.10.5.112:50302 fd=92 name= age=1109 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33671 addr=10.10.5.113:44096 fd=192 name= age=1049 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33668 addr=10.10.5.116:55214 fd=182 name= age=1050 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33749 addr=10.10.5.115:42840 fd=191 name= age=59 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33416 addr=10.10.5.116:46886 fd=135 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33716 addr=10.10.5.115:45284 fd=194 name= age=429 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33634 addr=10.10.5.113:49250 fd=101 name= age=1497 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33698 addr=10.10.5.116:46110 fd=96 name= age=691 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=113 qbuf-free=32655 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33737 addr=10.10.5.113:53680 fd=126 name= age=208 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33630 addr=10.10.5.116:40942 fd=187 name= age=1560 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33664 addr=10.10.5.115:48454 fd=161 name= age=1081 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33708 addr=10.10.5.111:52308 fd=147 name= age=510 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33719 addr=10.10.5.117:45224 fd=150 name= age=360 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33550 addr=10.10.5.116:59558 fd=122 name= age=2459 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33674 addr=10.10.5.117:57246 fd=103 name= age=1018 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33715 addr=10.10.5.117:49962 fd=109 name= age=448 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33720 addr=10.10.5.117:46528 fd=146 name= age=359 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33428 addr=10.10.5.111:54248 fd=154 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33730 addr=10.10.5.115:45920 fd=225 name= age=300 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33635 addr=10.10.5.116:47306 fd=125 name= age=1441 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33648 addr=10.10.5.114:60330 fd=98 name= age=1209 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33667 addr=10.10.5.113:51142 fd=121 name= age=1078 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33524 addr=10.10.5.113:60460 fd=176 name= age=2907 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33613 addr=10.10.5.111:46311 fd=99 name= age=1839 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33433 addr=10.10.5.113:35162 fd=156 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33437 addr=10.10.5.116:46890 fd=167 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33681 addr=10.10.5.111:57172 fd=183 name= age=908 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33728 addr=10.10.5.114:45450 fd=220 name= age=307 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33619 addr=10.10.5.115:53690 fd=132 name= age=1780 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33517 addr=10.10.5.113:51372 fd=180 name= age=2969 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33606 addr=10.10.5.113:34590 fd=217 name= age=1917 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33692 addr=10.10.5.111:50736 fd=211 name= age=789 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33440 addr=10.10.5.114:59274 fd=169 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33687 addr=10.10.5.117:32958 fd=190 name= age=837 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33673 addr=10.10.5.117:37910 fd=214 name= age=1048 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33584 addr=10.10.5.112:47148 fd=203 name= age=2135 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33512 addr=10.10.5.117:38308 fd=112 name= age=3099 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33446 addr=10.10.5.116:46898 fd=178 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33663 addr=10.10.5.112:34878 fd=120 name= age=1082 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33697 addr=10.10.5.112:35042 fd=110 name= age=720 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33693 addr=10.10.5.116:36788 fd=163 name= age=781 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33740 addr=10.10.5.116:59024 fd=151 name= age=182 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33587 addr=10.10.5.112:34070 fd=210 name= age=2102 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33470 addr=10.10.5.112:48442 fd=207 name= age=3831 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33627 addr=10.10.5.113:46236 fd=152 name= age=1589 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33177 addr=10.10.5.111:38718 fd=136 name= age=7119 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33735 addr=10.10.5.117:37340 fd=100 name= age=237 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33736 addr=10.10.5.113:48134 fd=117 name= age=217 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33703 addr=10.10.5.117:52794 fd=138 name= age=609 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33526 addr=10.10.5.112:33864 fd=209 name= age=2881 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33724 addr=10.10.5.111:43518 fd=162 name= age=358 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33707 addr=10.10.5.114:51952 fd=133 name= age=546 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33744 addr=10.10.5.116:38364 fd=184 name= age=91 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33745 addr=10.10.5.115:60120 fd=153 name= age=90 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33683 addr=10.10.5.112:59518 fd=116 name= age=843 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33597 addr=10.10.5.112:60016 fd=129 name= age=1923 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33717 addr=10.10.5.111:33812 fd=134 name= age=370 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33605 addr=10.10.5.112:60990 fd=188 name= age=1918 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33747 addr=10.10.5.115:60608 fd=111 name= age=88 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33670 addr=10.10.5.116:56522 fd=177 name= age=1049 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33738 addr=10.10.5.111:42706 fd=127 name= age=189 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33629 addr=10.10.5.116:56262 fd=172 name= age=1589 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33700 addr=10.10.5.115:42322 fd=114 name= age=689 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33601 addr=10.10.5.111:35084 fd=204 name= age=1920 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33644 addr=10.10.5.115:33804 fd=118 name= age=1378 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33746 addr=10.10.5.117:60576 fd=186 name= age=90 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33525 addr=10.10.5.112:33714 fd=179 name= age=2881 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33678 addr=10.10.5.113:50284 fd=115 name= age=909 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33552 addr=10.10.5.112:47780 fd=91 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33695 addr=10.10.5.111:56662 fd=216 name= age=780 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33628 addr=10.10.5.111:33842 fd=168 name= age=1589 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33554 addr=10.10.5.113:58578 fd=93 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33612 addr=10.10.5.115:44000 fd=104 name= age=1857 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33572 addr=10.10.5.114:39846 fd=164 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33691 addr=10.10.5.117:45762 fd=202 name= age=808 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33705 addr=10.10.5.114:38021 fd=145 name= age=608 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=7 oll=0 omem=0 events=r cmd=get user=default
id=33575 addr=10.10.5.114:39850 fd=170 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33739 addr=10.10.5.112:60598 fd=149 name= age=183 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=setex user=default
id=33582 addr=10.10.5.115:35252 fd=199 name= age=2158 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33726 addr=10.10.5.114:37676 fd=206 name= age=338 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33722 addr=10.10.5.113:54418 fd=198 name= age=359 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33561 addr=10.10.5.114:39838 fd=141 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33743 addr=10.10.5.113:53544 fd=94 name= age=98 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33748 addr=10.10.5.116:45276 fd=189 name= age=59 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33562 addr=10.10.5.114:39840 fd=142 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33733 addr=10.10.5.111:39452 fd=123 name= age=298 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33564 addr=10.10.5.111:57543 fd=148 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33653 addr=10.10.5.114:49940 fd=201 name= age=1176 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33567 addr=10.10.5.112:47790 fd=160 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33568 addr=10.10.5.114:39842 fd=155 name= age=2312 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33321 addr=10.10.5.114:59928 fd=130 name= age=4629 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33712 addr=10.10.5.117:35398 fd=165 name= age=479 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33549 addr=10.10.5.111:39852 fd=113 name= age=2460 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=33685 addr=10.10.5.115:34046 fd=159 name= age=839 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=get user=default

------ REGISTERS ------
19114:21314:M 03 May 2020 17:53:09.462 #
RAX:0000000000000000 RBX:00000000000001b3
RCX:0000000000001000 RDX:000000000000072f
RDI:00007f4240000000 RSI:00007f42400008b0
RBP:0000000000598e99 RSP:00007f42501fbfd0
R8 :0000000000000001 R9 :0000000000020750
R10:7562206568742074 R11:0000000000000206
R12:0000000000598de8 R13:0000000000000001
R14:0000000000000012 R15:0000000000000019
RIP:0000000000492683 EFL:0000000000010206
CSGSFS:0000000000000033
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfdf) -> 0000000111a28000
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfde) -> 00007f4a11a28000
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfdd) -> 000000000045c1cc
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfdc) -> fffffffffffffbe8
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfdb) -> 00007f3e21c41d0c
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfda) -> 00007f3e21c3da80
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd9) -> 00000000004e2100
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd8) -> 00007f3e21c41d0c
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd7) -> 0000000000456705
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd6) -> 00007f3e21c3da80
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd5) -> 00000000005eaff8
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd4) -> 00007f3e21c3da80
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd3) -> 00000000004e2164
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd2) -> 00007f3e21c41d0c
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd1) -> 0000000000005342
19114:21314:M 03 May 2020 17:53:09.462 # (00007f42501fbfd0) -> 00007f3e21c41d0c

------ MODULES INFO OUTPUT ------

------ FAST MEMORY TEST ------
19114:21314:M 03 May 2020 17:53:09.463 # Bio thread for job type #0 terminated
19114:21314:M 03 May 2020 17:53:09.463 # Bio thread for job type #1 terminated
19114:21314:M 03 May 2020 17:53:09.463 # Bio thread for job type #2 terminated
*** Preparing to test memory region 5eb000 (2260992 bytes)
*** Preparing to test memory region 163f000 (135168 bytes)
*** Preparing to test memory region 7f3db3a00000 (15351152640 bytes)
*** Preparing to test memory region 7f4146b00000 (2630877184 bytes)
*** Preparing to test memory region 7f41e3980000 (1282019328 bytes)
*** Preparing to test memory region 7f4234000000 (67244032 bytes)
*** Preparing to test memory region 7f423c000000 (135168 bytes)
*** Preparing to test memory region 7f4240000000 (135168 bytes)
*** Preparing to test memory region 7f424417e000 (48758784 bytes)
*** Preparing to test memory region 7f4246fff000 (8388608 bytes)
*** Preparing to test memory region 7f4247800000 (8388608 bytes)
*** Preparing to test memory region 7f4248000000 (135168 bytes)
*** Preparing to test memory region 7f424c180000 (11010048 bytes)
*** Preparing to test memory region 7f424ce00000 (8388608 bytes)
*** Preparing to test memory region 7f424d600000 (4194304 bytes)
*** Preparing to test memory region 7f424dbff000 (2097152 bytes)
*** Preparing to test memory region 7f424de00000 (8388608 bytes)
*** Preparing to test memory region 7f424e600000 (2097152 bytes)
*** Preparing to test memory region 7f424e9fd000 (8388608 bytes)
*** Preparing to test memory region 7f424f1fe000 (8388608 bytes)
*** Preparing to test memory region 7f424f9ff000 (8388608 bytes)
*** Preparing to test memory region 7f4250200000 (8388608 bytes)
*** Preparing to test memory region 7f4250a00000 (31803310080 bytes)
*** Preparing to test memory region 7f49b85bf000 (1342177280 bytes)
*** Preparing to test memory region 7f4a085c0000 (8388608 bytes)
*** Preparing to test memory region 7f4a08dc1000 (8388608 bytes)
*** Preparing to test memory region 7f4a095c2000 (8388608 bytes)
*** Preparing to test memory region 7f4a09dc3000 (8388608 bytes)
*** Preparing to test memory region 7f4a0a7d0000 (24576 bytes)
*** Preparing to test memory region 7f4a0a7d6000 (9437184 bytes)
*** Preparing to test memory region 7f4a11600000 (8388608 bytes)
*** Preparing to test memory region 7f4a12526000 (188416 bytes)
*** Preparing to test memory region 7f4a12779000 (8192 bytes)
*** Preparing to test memory region 7f4a12baf000 (8192 bytes)
*** Preparing to test memory region 7f4a13424000 (16384 bytes)
*** Preparing to test memory region 7f4a148bd000 (8192 bytes)
*** Preparing to test memory region 7f4a15225000 (8192 bytes)
*** Preparing to test memory region 7f4a156a7000 (4096 bytes)
*** Preparing to test memory region 7f4a15ed1000 (20480 bytes)
*** Preparing to test memory region 7f4a160ee000 (16384 bytes)
*** Preparing to test memory region 7f4a168fc000 (86016 bytes)
*** Preparing to test memory region 7f4a17129000 (4096 bytes)
*** Preparing to test memory region 7f4a17393000 (4096 bytes)
*** Preparing to test memory region 7f4a17592000 (90112 bytes)
*** Preparing to test memory region 7f4a175b3000 (8192 bytes)
*** Preparing to test memory region 7f4a175b7000 (4096 bytes)
.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.3036:3036:C

[eni9889]

I am running into the same issue. Any updates on this?

[JohnSully]

6.0 blocking

[JohnSully]

To be a bit more verbose, I have been able to repro this with the test suite but its a rare condition. I'm still trying to track down the underlying cause.

[eni9889]

Just FYI I’m running 5.3.3 and this is happening on a high load server.

[JohnSully]

Can you let me know which if any of the following features are used:

1. blocking commands (blop, etc)
2. pub/sub commands

If you use both which is used more frequently?

I've been running the test suite for the last 6 hours with my extra debugging logic and unfortunately the issue hasn't repro'd a second time. It's time to get more surgical. We know one side of the lock is free'ing the client due to disconnect, the remaining piece of the picture is who is waiting on the other side of the lock.

[JohnSully]

I got it, not a race condition at all - ignore my questions above. The assert is incorrect in a very subtle way:

(lock->m_ticket.m_active == lock->m_ticket.m_avail-1)

That equation relies upon m_avail wrapping as a uint16_t but the -1 promotes it to an integer. So when m_avail is 0 the comparison will be accidentally false. This situation could happen on average once in every 65536 unlocks. But under heavy load that can be hit relative quickly as you've experienced.

[JohnSully]

This fix is currently in unstable and will be released in 6.0