Crash report
=== REDIS BUG REPORT START: Cut & paste starting from here ===
19798:M 31 Oct 2022 09:19:29.013 # ------------------------------------------------
19798:M 31 Oct 2022 09:19:29.013 # !!! Software Failure. Press left mouse button to continue
19798:M 31 Oct 2022 09:19:29.013 # Guru Meditation: Duplicated key found in RDB file #rdb.c:2289
19798:M 31 Oct 2022 09:19:29.013 # (forcing SIGSEGV in order to print the stack trace)
19798:M 31 Oct 2022 09:19:29.013 # ------------------------------------------------
19798:M 31 Oct 2022 09:19:29.013 # Redis 6.0.5 crashed by signal: 11
19798:M 31 Oct 2022 09:19:29.013 # Crashed running the instruction at: 0x473b67
19798:M 31 Oct 2022 09:19:29.013 # Accessing address: 0xffffffffffffffff
19798:M 31 Oct 2022 09:19:29.013 # Failed assertion: <no assertion failed> (<no file>:0)
------ STACK TRACE ------
EIP:
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380(_serverPanic+0x117)[0x473b67]
Backtrace:
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380(logStackTrace+0x29)[0x475bc9]
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380(sigsegvHandler+0xa6)[0x476266]
/lib64/libpthread.so.0(+0xf630)[0x7f7e28155630]
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380(_serverPanic+0x117)[0x473b67]
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380(rdbLoadRio+0xb20)[0x45a860]
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380(rdbLoad+0x4c)[0x45a91c]
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380(loadDataFromDisk+0x91)[0x439061]
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380(main+0x429)[0x42c1d9]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f7e27d9a555]
/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380[0x42c4fd]
------ INFO OUTPUT ------
# Server
redis_version:6.0.5
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:465a69a185d30a05
redis_mode:standalone
os:Linux 3.10.0-1160.76.1.el7.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:4.9.1
process_id:19798
run_id:3d6fa1b3d5cda2789dcbeb52eb9462881cb7b21e
tcp_port:6380
uptime_in_seconds:6
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:6263578
executable:/gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server
config_file:
# Clients
connected_clients:0
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
# Memory
used_memory:3301747056
used_memory_human:3.07G
used_memory_rss:0
used_memory_rss_human:0B
used_memory_peak:3310134000
used_memory_peak_human:3.08G
used_memory_peak_perc:99.75%
used_memory_overhead:817120
used_memory_startup:804912
used_memory_dataset:3300929936
used_memory_dataset_perc:100.00%
allocator_allocated:0
allocator_active:0
allocator_resident:0
total_system_memory:50477309952
total_system_memory_human:47.01G
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:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:-nan
allocator_frag_bytes:0
allocator_rss_ratio:-nan
allocator_rss_bytes:0
rss_overhead_ratio:-nan
rss_overhead_bytes:0
mem_fragmentation_ratio:-nan
mem_fragmentation_bytes:0
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_clients_slaves:0
mem_clients_normal:0
mem_aof_buffer:0
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0
# Persistence
loading:1
rdb_changes_since_last_save:0
rdb_bgsave_in_progress:0
rdb_last_save_time:1667207962
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
loading_start_time:1667207962
loading_total_bytes:1380282883
loading_loaded_bytes:1004713772
loading_loaded_perc:72.79
loading_eta_seconds:2
# Stats
total_connections_received:1
total_commands_processed:0
instantaneous_ops_per_sec:0
total_net_input_bytes:0
total_net_output_bytes:0
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:0
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:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
# Replication
role:master
connected_slaves:0
master_replid:77d1aac0b57519ff7f1d265fdd323f73308aa3c9
master_replid2:0000000000000000000000000000000000000000
master_repl_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:1.996870
used_cpu_user:5.036283
used_cpu_sys_children:0.084851
used_cpu_user_children:0.043630
# Modules
# Commandstats
# Cluster
cluster_enabled:0
# Keyspace
db0:keys=202,expires=0,avg_ttl=0
------ CLIENT LIST OUTPUT ------
------ REGISTERS ------
19798:M 31 Oct 2022 09:19:29.014 #
RAX:0000000000000000 RBX:000000000055b969
RCX:ffffffffffffffff RDX:0000000000000000
RDI:0000000000000000 RSI:00007f7e28141a00
RBP:00000000000008f1 RSP:00007ffd1c672230
R8 :00007f7e29339080 R9 :00007f7e27dc52cd
R10:2d2d2d2d2d2d2d2d R11:0000000000000000
R12:ffffffffffffffff R13:00007f7e262098c3
R14:00007f7e2624d8b0 R15:00007f7e26306000
RIP:0000000000473b67 EFL:0000000000010202
CSGSFS:ffff000000000033
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c67223f) -> 00000000004494fd
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c67223e) -> 0000000000000000
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c67223d) -> 00007ffd1c6728f0
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c67223c) -> 00007ffd1c6722e4
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c67223b) -> 000000000043cab6
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c67223a) -> 00007f7e2624d8b0
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672239) -> 0000000000000000
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672238) -> 0000000000000000
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672237) -> 656c696620424452
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672236) -> 206e6920646e756f
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672235) -> 662079656b206465
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672234) -> 746163696c707544
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672233) -> 00007ffd1c672350
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672232) -> 00007ffd1c672420
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672231) -> 0000003000000018
19798:M 31 Oct 2022 09:19:29.014 # (00007ffd1c672230) -> 00007ffd1c6728f0
------ MODULES INFO OUTPUT ------
------ FAST MEMORY TEST ------
19798:M 31 Oct 2022 09:19:29.014 # Bio thread for job type #0 terminated
19798:M 31 Oct 2022 09:19:29.014 # Bio thread for job type #1 terminated
19798:M 31 Oct 2022 09:19:29.014 # Bio thread for job type #2 terminated
*** Preparing to test memory region 5cc000 (2277376 bytes)
*** Preparing to test memory region 1066000 (270336 bytes)
*** Preparing to test memory region 7f7d33000000 (3437232128 bytes)
*** Preparing to test memory region 7f7dffe7c000 (603455488 bytes)
*** Preparing to test memory region 7f7e23dfd000 (8388608 bytes)
*** Preparing to test memory region 7f7e245fe000 (8388608 bytes)
*** Preparing to test memory region 7f7e24dff000 (8388608 bytes)
*** Preparing to test memory region 7f7e25600000 (8388608 bytes)
*** Preparing to test memory region 7f7e25e00000 (8388608 bytes)
*** Preparing to test memory region 7f7e26bc5000 (8192 bytes)
*** Preparing to test memory region 7f7e26ddf000 (8192 bytes)
*** Preparing to test memory region 7f7e28141000 (20480 bytes)
*** Preparing to test memory region 7f7e2835e000 (16384 bytes)
*** Preparing to test memory region 7f7e287c1000 (16384 bytes)
*** Preparing to test memory region 7f7e29337000 (45056 bytes)
*** Preparing to test memory region 7f7e29361000 (20480 bytes)
*** Preparing to test memory region 7f7e29368000 (4096 bytes)
.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O
Fast memory test PASSED, however your memory can still be broken. Please run a memory test for several hours if possible.
------ DUMPING CODE AROUND EIP ------
Symbol: _serverPanic (base: 0x473a50)
Module: /gns/area/certified/external/redis/io/redisbinary/redis-bin-6.0.5-6.0.5/redis-bin-6.0.5/redis-6.0.5/redis-server 0.0.0.0:6380 (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x473a50 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
19798:M 31 Oct 2022 09:19:41.751 # dump of function (hexdump of 407 bytes):
555389f54889fb4881ecd801000084c048898c24380100004c898424400100004c898c244801000074400f298424500100000f298c24600100000f299424700100000f299c24800100000f29a424900100000f29ac24a00100000f29b424b00100000f29bc24c0010000488d8424f0010000488d4c2408488d7c2420be000100004889442410488d842420010000c744240818000000c744240c300000004889442418e8a870fbff8b05562c380085c07505e839f6ffffbe90e85600bf0300000031c0e8b8f4fbffbec8e85600bf0300000031c0e8a7f4fbff488d5424204189e84889d9bed5d05500bf0300000031c0e88bf4fbffbe08e95600bf0300000031c0e87af4fbffbe90e85600bf0300000031c0e869f4fbffc60425ffffffff784881c4d80100005b5dc30f1f800000000041574156415541544989f455534889d34889fdba040000004889df4881ece80200000fb6014989cd488d74241483e00f0fc889442414e8a5f6ffff4889ef4c89e6e8aa96fdff410fb655004889c589d083e00f0f84c70000003c010f843f0200003c020f849702
Function at 0x432fd0 is serverLog
Function at 0x473260 is mixDigest
Function at 0x44d270 is getExpire
=== REDIS BUG REPORT END. Make sure to include from START to END. ===
Comment From: CharlesChen888
Looks like you have duplicated key in RDB file.
Comment From: oranagra
how was that RDB produced? same redis version just doing a restart?
Comment From: josidd
Yes it was the same version of Redis (6.0.5) doing a restart
Comment From: oranagra
well, i'm clueless. without being able to reproduce it (know the sequence of commands that caused it) not sure we can do much. maybe somehow the file on the disk got corrupted. maybe if you'll analyze that rdb file with some tool (e.g. redis-rdb-tools) you'll find the name and type of that duplicate key and this could be a hint leading us to some realization.
Comment From: josidd
It found an empty '' duplicate key in the rdb file
27565:C 31 Oct 2022 18:18:50.795 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
27565:C 31 Oct 2022 18:18:50.795 # Redis version=6.0.5, bits=64, commit=00000000, modified=0, pid=27565, just started
27565:C 31 Oct 2022 18:18:50.795 # Configuration loaded
27565:M 31 Oct 2022 18:18:50.796 * Increased maximum number of open files to 10032 (it was originally set to 1024).
27565:M 31 Oct 2022 18:18:50.797 * Running mode=standalone, port=6380.
27565:M 31 Oct 2022 18:18:50.797 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
27565:M 31 Oct 2022 18:18:50.797 # Server initialized
27565:M 31 Oct 2022 18:18:50.797 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
27565:M 31 Oct 2022 18:18:50.798 * Loading RDB produced by version 6.0.5
27565:M 31 Oct 2022 18:18:50.798 * RDB age 257423 seconds
27565:M 31 Oct 2022 18:18:50.798 * RDB memory usage when created 4319.92 Mb
27565:M 31 Oct 2022 18:18:56.863 # RDB has duplicated key '' in DB 0
Comment From: oranagra
does your application create such keys? do you have any clue what type it is and what it contains? again maybe redis-rdb-tools or alike can help here.