After the migration from the old database to newest stable 5.x version we get frequent redis crashes. It's caused by empty ZSET objects in our db.
127.0.0.1:16379> ZSCAN product:15969279:likes 1 1) "0" 2) (empty list or set) 127.0.0.1:16379> type product:15969279:likes zset
where empty ZSET should return type none.
127.0.0.1:16379> ZADD product:0:likes 1 “one” (integer) 1 127.0.0.1:16379> ZRANK product:0:likes ‘None’ (nil) 127.0.0.1:16379> ZREM product:0:likes “one” (integer) 1 127.0.0.1:16379> ZRANK product:0:likes ‘None’ (nil) 127.0.0.1:16379> type product:0:likes none 127.0.0.1:16379> type product:15969279:likes zset 127.0.0.1:16379> ZADD product:0:likes 1 “one” (integer) 1 127.0.0.1:16379> type product:0:likes zset
=== REDIS BUG REPORT START: Cut & paste starting from here === 1196:M 05 Nov 2019 09:10:40.896 # === ASSERTION FAILED === 1196:M 05 Nov 2019 09:10:40.896 # ==> t_zset.c:1483 'eptr != NULL' is not true 1196:M 05 Nov 2019 09:10:40.896 # (forcing SIGSEGV to print the bug report.) 1196:M 05 Nov 2019 09:10:40.896 # Redis 5.0.6 crashed by signal: 11 1196:M 05 Nov 2019 09:10:40.896 # Crashed running the instruction at: 0x471e7a 1196:M 05 Nov 2019 09:10:40.896 # Accessing address: 0xffffffffffffffff 1196:M 05 Nov 2019 09:10:40.896 # Failed assertion: eptr != NULL (t_zset.c:1483)
------ STACK TRACE ------ EIP: /usr/local/bin/redis-server 0.0.0.0:16379(_serverAssert+0x6a)[0x471e7a]
Backtrace: /usr/local/bin/redis-server 0.0.0.0:16379(logStackTrace+0x45)[0x474355] /usr/local/bin/redis-server 0.0.0.0:16379(sigsegvHandler+0xb9)[0x474b19] /lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fdedabe0390] /usr/local/bin/redis-server 0.0.0.0:16379(_serverAssert+0x6a)[0x471e7a] /usr/local/bin/redis-server 0.0.0.0:16379(zsetRank+0x232)[0x45cf02] /usr/local/bin/redis-server 0.0.0.0:16379(zrankGenericCommand+0x5b)[0x46055b] /usr/local/bin/redis-server 0.0.0.0:16379(call+0xaf)[0x4300df] /usr/local/bin/redis-server 0.0.0.0:16379(processCommand+0x377)[0x4307a7] /usr/local/bin/redis-server 0.0.0.0:16379(processInputBuffer+0x175)[0x440c15] /usr/local/bin/redis-server 0.0.0.0:16379(aeProcessEvents+0x36d)[0x429d6d] /usr/local/bin/redis-server 0.0.0.0:16379(aeMain+0x2b)[0x429f9b] /usr/local/bin/redis-server 0.0.0.0:16379(main+0x4ae)[0x426b4e] /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fdeda825830] /usr/local/bin/redis-server 0.0.0.0:16379(_start+0x29)[0x426db9]
------ INFO OUTPUT ------
Server
redis_version:5.0.6 redis_git_sha1:00000000 redis_git_dirty:0 redis_build_id:10c194c52891688f redis_mode:standalone os:Linux 4.4.0-1096-aws x86_64 arch_bits:64 multiplexing_api:epoll atomicvar_api:atomic-builtin gcc_version:5.4.0 process_id:1196 run_id:66e62634de7a54d514d053dfc4d4665307bc6bd6 tcp_port:16379 uptime_in_seconds:403 uptime_in_days:0 hz:10 configured_hz:10 lru_clock:12663952 executable:/usr/local/bin/redis-server config_file:/etc/redis/redis.conf
Clients
connected_clients:1 client_recent_max_input_buffer:2 client_recent_max_output_buffer:0 blocked_clients:0
Memory
used_memory:6946473624 used_memory_human:6.47G used_memory_rss:7156756480 used_memory_rss_human:6.67G used_memory_peak:7038049008 used_memory_peak_human:6.55G used_memory_peak_perc:98.70% used_memory_overhead:402937550 used_memory_startup:512856 used_memory_dataset:6543536074 used_memory_dataset_perc:94.21% allocator_allocated:6946620792 allocator_active:7060418560 allocator_resident:7159754752 total_system_memory:16678178816 total_system_memory_human:15.53G 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:1.02 allocator_frag_bytes:113797768 allocator_rss_ratio:1.01 allocator_rss_bytes:99336192 rss_overhead_ratio:1.00 rss_overhead_bytes:-2998272 mem_fragmentation_ratio:1.03 mem_fragmentation_bytes:210301784 mem_not_counted_for_evict:0 mem_replication_backlog:0 mem_clients_slaves:0 mem_clients_normal:49694 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:120881 rdb_bgsave_in_progress:0 rdb_last_save_time:1572944637 rdb_last_bgsave_status:ok rdb_last_bgsave_time_sec:-1 rdb_current_bgsave_time_sec:-1 rdb_last_cow_size:0 aof_enabled:1 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 aof_current_size:2246126293 aof_base_size:2233261988 aof_pending_rewrite:0 aof_buffer_length:0 aof_rewrite_buffer_length:0 aof_pending_bio_fsync:0 aof_delayed_fsync:0
Stats
total_connections_received:1 total_commands_processed:390 instantaneous_ops_per_sec:0 total_net_input_bytes:141 total_net_output_bytes:39 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:225675 expired_stale_perc:30.18 expired_time_cap_reached_count: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
Replication
role:master connected_slaves:0 master_replid:ecbbca6fbe1ffc203407e0cba2150cf4566f9205 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:3.152000 used_cpu_user:43.004000 used_cpu_sys_children:0.000000 used_cpu_user_children:0.000000
Commandstats
cmdstat_auth:calls=1,usec=3,usec_per_call=3.00
Cluster
cluster_enabled:0
Keyspace
db0:keys=6912085,expires=1750230,avg_ttl=304662992
------ CLIENT LIST OUTPUT ------ id=3 addr=127.0.0.1:50866 fd=8 name= age=104 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=54 qbuf-free=32714 obl=0 oll=0 omem=0 events=r cmd=zrank
------ CURRENT CLIENT INFO ------ id=3 addr=127.0.0.1:50866 fd=8 name= age=104 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=54 qbuf-free=32714 obl=0 oll=0 omem=0 events=r cmd=zrank argv[0]: 'ZRANK' argv[1]: 'product:15969279:likes' argv[2]: 'None' 1196:M 05 Nov 2019 09:10:40.898 # key 'product:15969279:likes' found in DB containing the following object: 1196:M 05 Nov 2019 09:10:40.898 # Object type: 3 1196:M 05 Nov 2019 09:10:40.898 # Object encoding: 5 1196:M 05 Nov 2019 09:10:40.898 # Object refcount: 1 1196:M 05 Nov 2019 09:10:40.898 # Sorted set size: 0
------ REGISTERS ------ 1196:M 05 Nov 2019 09:10:40.898 # RAX:0000000000000000 RBX:00000000000005cb RCX:0000000000000000 RDX:0000000000000000 RDI:00007fdedabc9b20 RSI:0000000000000000 RBP:000000000055935f RSP:00007ffd62c63d20 R8 :00007fdedb71bf80 R9 :0000000000000001 R10:000000000000002a R11:0000000000000246 R12:000000000055938f R13:0000000000000000 R14:00007fde636ec5d0 R15:000000000000000f RIP:0000000000471e7a EFL:0000000000010202 CSGSFS:0000000000000033 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d2f) -> 00007fdd1bb6c800 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d2e) -> 000000020000002c 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d2d) -> 000000000046055b 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d2c) -> 00059695ce69f1d0 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d2b) -> 0000000000000000 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d2a) -> 00007fde02e55b18 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d29) -> 00007fde636ec5e0 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d28) -> 00007fdd1bb6c800 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d27) -> 3d6a3d3e9c211d00 1196:M 05 Nov 2019 09:10:40.898 # (00007ffd62c63d26) -> 00007fde02e55b18 1196:M 05 Nov 2019 09:10:40.899 # (00007ffd62c63d25) -> 0000000000000000 1196:M 05 Nov 2019 09:10:40.899 # (00007ffd62c63d24) -> 00007fdd1bb6c800 1196:M 05 Nov 2019 09:10:40.899 # (00007ffd62c63d23) -> 000000000045cf02 1196:M 05 Nov 2019 09:10:40.899 # (00007ffd62c63d22) -> 00007fde02e55b2b 1196:M 05 Nov 2019 09:10:40.899 # (00007ffd62c63d21) -> 0000000000000000 1196:M 05 Nov 2019 09:10:40.899 # (00007ffd62c63d20) -> 00007fde636ec5e0
------ FAST MEMORY TEST ------ 1196:M 05 Nov 2019 09:10:40.899 # Bio thread for job type #0 terminated 1196:M 05 Nov 2019 09:10:40.899 # Bio thread for job type #1 terminated 1196:M 05 Nov 2019 09:10:40.899 # Bio thread for job type #2 terminated *** Preparing to test memory region 7ae000 (2248704 bytes) *** Preparing to test memory region 1322000 (135168 bytes) *** Preparing to test memory region 7fdcfb600000 (7566524416 bytes) *** Preparing to test memory region 7fdebe7fd000 (436207616 bytes) *** Preparing to test memory region 7fded87fe000 (8388608 bytes) *** Preparing to test memory region 7fded8fff000 (8388608 bytes) *** Preparing to test memory region 7fded9800000 (8388608 bytes) *** Preparing to test memory region 7fdeda000000 (8388608 bytes) *** Preparing to test memory region 7fdedabcb000 (16384 bytes) *** Preparing to test memory region 7fdedade8000 (16384 bytes) *** Preparing to test memory region 7fdedb71a000 (24576 bytes) *** Preparing to test memory region 7fdedb728000 (4096 bytes) .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: _serverAssert (base: 0x471e10) Module: /usr/local/bin/redis-server 0.0.0.0:16379 (base 0x400000) $ xxd -r -p /tmp/dump.hex /tmp/dump.bin $ objdump --adjust-vma=0x471e10 -D -b binary -m i386:x86-64 /tmp/dump.bin
1196:M 05 Nov 2019 09:11:28.723 # dump of function (hexdump of 234 bytes): 8b05a6e2330041544989fc554889f55389d385c07505e8b5fdffffbe90dc5500bf0300000031c0e834bbfbff4d89e089d94889eabea9dc5500bf0300000031c0e81bbbfbffbe50c95500bf0300000031c04c892540e2330048892d41e23300891d43e23300e8f6bafbffc60425ffffffff785b5d415cc3660f1f8400000000004154554989fc534881ec900000008b3d18e2330064488b042528000000488984248800000031c085ff0f842101000031c0be80c95500bf03000000e8a0bafbff418b9424a000000031c0bec4dc5500bf0300000031ed31dbe883bafbff418b54240831c0bed7dc5500bf
=== REDIS BUG REPORT END. Make sure to include from START to END. ===
Please report the crash by opening an issue on github:
http://github.com/antirez/redis/issues
Suspect RAM error? Use redis-server --test-memory to verify it.
2542:C 05 Nov 2019 09:11:29.502 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo 2542:C 05 Nov 2019 09:11:29.502 # Redis version=5.0.6, bits=64, commit=00000000, modified=0, pid=2542, just started 2542:C 05 Nov 2019 09:11:29.502 # Configuration loaded 2542:C 05 Nov 2019 09:11:29.502 # systemd supervision requested, but NOTIFY_SOCKET not found 2542:M 05 Nov 2019 09:11:29.503 # You requested maxclients of 10000 requiring at least 10032 max file descriptors. 2542:M 05 Nov 2019 09:11:29.503 # Server can't set maximum open files to 10032 because of OS error: Operation not permitted. 2542:M 05 Nov 2019 09:11:29.503 # Current maximum open files is 4096. maxclients has been reduced to 4064 to compensate for low ulimit. If you need higher maxclients increase 'ulimit -n'. 2542:M 05 Nov 2019 09:11:29.503 * Running mode=standalone, port=16379. 2542:M 05 Nov 2019 09:11:29.503 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128. 2542:M 05 Nov 2019 09:11:29.503 # Server initialized 2542:M 05 Nov 2019 09:11:29.504 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled. 2542:M 05 Nov 2019 09:11:29.504 * Reading RDB preamble from AOF file...
Comment From: antirez
Hello @CombatCode, thanks for the bug report. What was the Redis version that generated that RDB files? I guess veeeery old? :-D We should still be able to fix the problem when reloading the data back to remove completely the empty sorted sets.
Comment From: CombatCode
@antirez honestly that was ardb (https://github.com/yinqiwen/ardb) dump. What is the best recommended way to make sure that redis will not crash on that case?
Comment From: itamarhaber
Honesty is the best :)
The recommended way to avoid this, imo, is to refrain from using dumps from non-Redis sources.