Skip to content

KeyDB server crashes during client side caching test #183

@surenkajan

Description

@surenkajan

KeyDB server crashes when it is sending invalidate message to its clients.

Log Files

=== KEYDB BUG REPORT START: Cut & paste starting from here ===
9775:9793:M 15 May 2020 14:37:37.255 # === ASSERTION FAILED ===
9775:9793:M 15 May 2020 14:37:37.255 # ==> networking.cpp:255 'c->conn == nullptr || c->lock.fOwnLock()' is not true
9775:9793:M 15 May 2020 14:37:37.255 # (forcing SIGSEGV to print the bug report.)
9775:9793:M 15 May 2020 14:37:37.255 # KeyDB 0.0.0 crashed by signal: 11
9775:9793:M 15 May 2020 14:37:37.255 # Crashed running the instruction at: 0x55f4b5953b7e
9775:9793:M 15 May 2020 14:37:37.255 # Accessing address: 0xffffffffffffffff
9775:9793:M 15 May 2020 14:37:37.255 # Failed assertion: c->conn == nullptr || c->lock.fOwnLock() (networking.cpp:255)

------ STACK TRACE ------
EIP:
./keydb-server-3543a3c 127.0.0.1:8000(_serverAssert+0x7e) [0x55f4b5953b7e]

Backtrace:
./keydb-server-3543a3c 127.0.0.1:8000(logStackTrace(ucontext_t*)+0x6b) [0x55f4b59553db]
./keydb-server-3543a3c 127.0.0.1:8000(sigsegvHandler(int, siginfo_t*, void*)+0xc9) [0x55f4b5955b79]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890) [0x7f5ddf07d890]
./keydb-server-3543a3c 127.0.0.1:8000(_serverAssert+0x7e) [0x55f4b5953b7e]
./keydb-server-3543a3c 127.0.0.1:8000(prepareClientToWrite(client*, bool)+0x184) [0x55f4b5910644]
./keydb-server-3543a3c 127.0.0.1:8000(addReplyProtoCore(client*, char const*, unsigned long, bool)+0x1d) [0x55f4b5910acd]
./keydb-server-3543a3c 127.0.0.1:8000(addReplyLongLongWithPrefixCore(client*, long long, char, bool)+0x77) [0x55f4b5912157]
./keydb-server-3543a3c 127.0.0.1:8000(sendTrackingMessage(client*, char const*, unsigned long, int)+0x5c) [0x55f4b59ae67c]
./keydb-server-3543a3c 127.0.0.1:8000(trackingInvalidateKey(redisObject*)+0x11b) [0x55f4b59ae94b]
./keydb-server-3543a3c 127.0.0.1:8000(setGenericCommand(client*, int, redisObject*, redisObject*, redisObject*, int, redisObject*, redisObject*)+0xd1) [0x55f4b5937cf1]
./keydb-server-3543a3c 127.0.0.1:8000(setCommand(client*)+0x131) [0x55f4b5937f71]
./keydb-server-3543a3c 127.0.0.1:8000(call(client*, int)+0xd1) [0x55f4b58fd851]
./keydb-server-3543a3c 127.0.0.1:8000(processCommand(client*, int)+0x5bb) [0x55f4b5901bab]
./keydb-server-3543a3c 127.0.0.1:8000(processCommandAndResetClient(client*, int)+0x21) [0x55f4b590c951]
./keydb-server-3543a3c 127.0.0.1:8000(processInputBuffer(client*, int)+0x17b) [0x55f4b5911d5b]
./keydb-server-3543a3c 127.0.0.1:8000(readQueryFromClient(connection*)+0x438) [0x55f4b5914e58]
./keydb-server-3543a3c 127.0.0.1:8000(+0x105337) [0x55f4b59b0337]
./keydb-server-3543a3c 127.0.0.1:8000(ProcessEventCore+0x124) [0x55f4b58f5b04]
./keydb-server-3543a3c 127.0.0.1:8000(aeProcessEvents+0x18d) [0x55f4b58f5ddd]
./keydb-server-3543a3c 127.0.0.1:8000(aeMain+0x45) [0x55f4b58f6215]
./keydb-server-3543a3c 127.0.0.1:8000(workerThreadMain(void*)+0x97) [0x55f4b58fa8a7]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7f5ddf0726db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f5dded9b88f]

------ INFO OUTPUT ------
# Server
redis_version:0.0.0
redis_git_sha1:3543a3c7
redis_git_dirty:0
redis_build_id:8b3bddc340b133ce
redis_mode:standalone
os:Linux 4.15.0-20-generic x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:7.3.0
process_id:9775
run_id:2894ed20181beb20081a8f9efbe17907af0c3dc1
tcp_port:8000
uptime_in_seconds:63
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:12509553
executable:/home/paas/Kajan/VerificationSpreadSheet/./keydb-server-3543a3c
config_file:/home/paas/Kajan/VerificationSpreadSheet/./keydb.conf

# Clients
connected_clients:2
client_recent_max_input_buffer:2
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:1
clients_in_timeout_table:0
current_client_thread:0
thread_0_clients:2

# Memory
used_memory:9151608
used_memory_human:8.73M
used_memory_rss:20258816
used_memory_rss_human:19.32M
used_memory_peak:9151608
used_memory_peak_human:8.73M
used_memory_peak_perc:100.02%
used_memory_overhead:9136056
used_memory_startup:9066808
used_memory_dataset:15552
used_memory_dataset_perc:18.34%
allocator_allocated:9540360
allocator_active:10084352
allocator_resident:16535552
total_system_memory:405355134976
total_system_memory_human:377.52G
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.06
allocator_frag_bytes:543992
allocator_rss_ratio:1.64
allocator_rss_bytes:6451200
rss_overhead_ratio:1.23
rss_overhead_bytes:3723264
mem_fragmentation_ratio:2.22
mem_fragmentation_bytes:11149776
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_clients_slaves:0
mem_clients_normal:67112
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:1
rdb_bgsave_in_progress:0
rdb_last_save_time:1589567794
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:0
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:3
total_commands_processed:4
instantaneous_ops_per_sec:0
total_net_input_bytes:96
total_net_output_bytes:287
instantaneous_input_kbps:0.00
instantaneous_output_kbps:0.00
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:0
evicted_keys:0
keyspace_hits:1
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:0
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:1
tracking_total_items:1
unexpected_error_replies:0

# Replication
role:master
connected_slaves:0
master_replid:914cb106633d05945fbd4059744bc53535a09544
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
master_repl_meaningful_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:53687091200
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

# CPU
used_cpu_sys:0.014585
used_cpu_user:0.024308
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
server_threads:1
long_lock_waits:0

# Modules

# Commandstats
cmdstat_hello:calls=1,usec=5,usec_per_call=5.00
cmdstat_client:calls=1,usec=14,usec_per_call=14.00
cmdstat_set:calls=1,usec=11,usec_per_call=11.00
cmdstat_get:calls=1,usec=4,usec_per_call=4.00

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=1,expires=0,avg_ttl=0

------ CLIENT LIST OUTPUT ------
id=4 addr=127.0.0.1:49258 fd=85 name= age=44 idle=7 flags=t db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=get user=default
id=5 addr=127.0.0.1:49292 fd=86 name= age=35 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=14 qbuf-free=32754 obl=0 oll=0 omem=0 events=r cmd=set user=default

------ CURRENT CLIENT INFO ------
id=5 addr=127.0.0.1:49292 fd=86 name= age=35 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=14 qbuf-free=32754 obl=0 oll=0 omem=0 events=r cmd=set user=default
argv[0]: 'set'
argv[1]: 'foo'
argv[2]: 'bar2'
9775:9793:M 15 May 2020 14:37:37.256 # key 'foo' found in DB containing the following object:
9775:9793:M 15 May 2020 14:37:37.256 # Object type: 0
9775:9793:M 15 May 2020 14:37:37.256 # Object encoding: 8
9775:9793:M 15 May 2020 14:37:37.256 # Object refcount: 2
9775:9793:M 15 May 2020 14:37:37.256 # Object raw string len: 4
9775:9793:M 15 May 2020 14:37:37.256 # Object raw string content: "bar2"

------ REGISTERS ------
9775:9793:M 15 May 2020 14:37:37.256 #
RAX:0000000000000000 RBX:00000000000000ff
RCX:0000000000000b40 RDX:0000000000000000
RDI:00007f5ddf066760 RSI:00007f5ddf0678c0
RBP:000055f4b5a501a8 RSP:00007f5dd51fba80
R8 :00007f5ddf0678c0 R9 :00007f5dd51fe700
R10:00000000ffffffd6 R11:0000000000000000
R12:000055f4b5a50ce0 R13:0000000000000004
R14:000055f4b5a6cc74 R15:0000000000000000
RIP:000055f4b5953b7e EFL:0000000000010202
CSGSFS:002b000000000033
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba8f) -> 000055f4b5912157
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba8e) -> 0000000000000000
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba8d) -> 00007f5dd51fbb00
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba8c) -> 00007f5dd44075c0
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba8b) -> 0000000000000000
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba8a) -> 0000000000000000
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba89) -> 000055f4b5910acd
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba88) -> 00007f5dd51fbb00
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba87) -> 00007f5dd44075c0
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba86) -> 0000000000000000
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba85) -> 000000000000b000
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba84) -> 0000000100000000
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba83) -> 000055f4b5910644
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba82) -> fffffffffffffbe8
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba81) -> 0000000000000000
9775:9793:M 15 May 2020 14:37:37.256 # (00007f5dd51fba80) -> 00007f5dd44075c0

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

------ FAST MEMORY TEST ------
9775:9793:M 15 May 2020 14:37:37.256 # Bio thread for job type #0 terminated
9775:9793:M 15 May 2020 14:37:37.256 # Bio thread for job type #1 terminated
9775:9793:M 15 May 2020 14:37:37.256 # Bio thread for job type #2 terminated
*** Preparing to test memory region 55f4b5cba000 (2260992 bytes)
*** Preparing to test memory region 55f4b76f3000 (471040 bytes)
*** Preparing to test memory region 7f5dc8000000 (135168 bytes)
*** Preparing to test memory region 7f5dcf800000 (8388608 bytes)
*** Preparing to test memory region 7f5dd0000000 (135168 bytes)
*** Preparing to test memory region 7f5dd4400000 (4194304 bytes)
*** Preparing to test memory region 7f5dd49ff000 (8388608 bytes)
*** Preparing to test memory region 7f5dd5200000 (8388608 bytes)
*** Preparing to test memory region 7f5dd5a00000 (6291456 bytes)
*** Preparing to test memory region 7f5dd60b5000 (8388608 bytes)
*** Preparing to test memory region 7f5dd68b6000 (8388608 bytes)
*** Preparing to test memory region 7f5dd72be000 (8388608 bytes)
*** Preparing to test memory region 7f5dd7cca000 (24576 bytes)
*** Preparing to test memory region 7f5dd7ee8000 (8192 bytes)
*** Preparing to test memory region 7f5dd8300000 (17825792 bytes)
*** Preparing to test memory region 7f5dd9807000 (188416 bytes)
*** Preparing to test memory region 7f5dd9b3d000 (4096 bytes)
*** Preparing to test memory region 7f5dd9d87000 (4096 bytes)
*** Preparing to test memory region 7f5dda813000 (4096 bytes)
*** Preparing to test memory region 7f5ddad42000 (4096 bytes)
*** Preparing to test memory region 7f5ddb691000 (4096 bytes)
*** Preparing to test memory region 7f5ddbd07000 (8192 bytes)
*** Preparing to test memory region 7f5ddc349000 (4096 bytes)
*** Preparing to test memory region 7f5ddd06f000 (4096 bytes)
*** Preparing to test memory region 7f5ddda69000 (8192 bytes)
*** Preparing to test memory region 7f5dde17e000 (12288 bytes)
*** Preparing to test memory region 7f5ddf067000 (16384 bytes)
*** Preparing to test memory region 7f5ddf286000 (16384 bytes)
*** Preparing to test memory region 7f5ddfbca000 (16384 bytes)
*** Preparing to test memory region 7f5de0661000 (114688 bytes)
*** Preparing to test memory region 7f5de0689000 (4096 bytes)
.O.O.O.O.O.O.Segmentation fault (core dumped)

To Reproduce

  1. Start KeyDB server
  2. Start Client-01 (telnet client)
  3. Start Client-02 (telnet client)
  4. Client-02 set one key (e.g: set k1 v1)
  5. Client-01 enable RESP3 using hello 3
  6. Client-01 enables tracking by issuing CLIENT TRACKING ON command
  7. Client-01 gets one key (e.g: get k1)
  8. Client-02 changes the value of same key (e.g: set k1 v2)

Client-01 should get the invalidate message from Server since it got changed by another client. But Keydb-server crashes with above error message.

Binary Version:
KeyDB-server binary is built from unstable branch (Commit hash: 3543a3c)

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions