Redis 4.0.10 Bug Report

[davissp14]

=== REDIS BUG REPORT START: Cut & paste starting from here ===
9:S 29 Jan 10:59:39.257 # Redis 4.0.10 crashed by signal: 11
9:S 29 Jan 10:59:39.257 # Crashed running the instruction at: 0x558e3b741377
9:S 29 Jan 10:59:39.257 # Accessing address: 0x50
9:S 29 Jan 10:59:39.257 # Failed assertion: (:0)

------ STACK TRACE ------
EIP:
/usr/local/bin/redis-server 0.0.0.0:6379(dictAddRaw+0x17)[0x558e3b741377]

Backtrace:
/usr/local/bin/redis-server 0.0.0.0:6379(logStackTrace+0x37)[0x558e3b784ad7]
/usr/local/bin/redis-server 0.0.0.0:6379(sigsegvHandler+0xb0)[0x558e3b785200]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110c0)[0x7f8235b360c0]
/usr/local/bin/redis-server 0.0.0.0:6379(dictAddRaw+0x17)[0x558e3b741377]
/usr/local/bin/redis-server 0.0.0.0:6379(dictAdd+0x11)[0x558e3b741561]
/usr/local/bin/redis-server 0.0.0.0:6379(blockForKeys+0x5a)[0x558e3b76988a]
/usr/local/bin/redis-server 0.0.0.0:6379(brpoplpushCommand+0xce)[0x558e3b76a1fe]
/usr/local/bin/redis-server 0.0.0.0:6379(loadAppendOnlyFile+0x24c)[0x558e3b7809cc]
/usr/local/bin/redis-server 0.0.0.0:6379(loadDataFromDisk+0xbc)[0x558e3b7490bc]
/usr/local/bin/redis-server 0.0.0.0:6379(main+0x42f)[0x558e3b73c5cf]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)[0x7f82357a62e1]
/usr/local/bin/redis-server 0.0.0.0:6379(_start+0x2a)[0x558e3b73c97a]

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

Server

redis_version:4.0.10
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:33b48e944488fc52
redis_mode:standalone
os:Linux 4.4.0-141-generic x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:6.3.0
process_id:9
run_id:7733aaac45bb6876e9e283d32cfab94185c6354e
tcp_port:6379
uptime_in_seconds:46
uptime_in_days:0
hz:10
lru_clock:5255642
executable:/usr/local/bin/redis-server
config_file:/conf/redis/redis.conf

Clients

connected_clients:2
client_longest_output_list:0
client_biggest_input_buf:0
blocked_clients:0

Memory

used_memory:5752576
used_memory_human:5.49M
used_memory_rss:0
used_memory_rss_human:0B
used_memory_peak:858716888
used_memory_peak_human:818.94M
used_memory_peak_perc:0.67%
used_memory_overhead:887540
used_memory_startup:786680
used_memory_dataset:4865036
used_memory_dataset_perc:97.97%
total_system_memory:67543195648
total_system_memory_human:62.90G
used_memory_lua:46080
used_memory_lua_human:45.00K
maxmemory:858993459
maxmemory_human:819.20M
maxmemory_policy:noeviction
mem_fragmentation_ratio:0.00
mem_allocator:jemalloc-4.0.3
active_defrag_running:0
lazyfree_pending_objects:0

Persistence

loading:1
rdb_changes_since_last_save:1124785
rdb_bgsave_in_progress:0
rdb_last_save_time:1548759514
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
loading_start_time:1548759514
loading_total_bytes:862901527
loading_loaded_bytes:862094334
loading_loaded_perc:99.91
loading_eta_seconds:0

Stats

total_connections_received:11
total_commands_processed:164722
instantaneous_ops_per_sec:0
total_net_input_bytes:1174
total_net_output_bytes:21981
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
evicted_keys:0
keyspace_hits:41168
keyspace_misses:3
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:slave
master_host:172.30.11.219
master_port:6379
master_link_status:down
master_last_io_seconds_ago:-1
master_sync_in_progress:0
slave_repl_offset:1
master_link_down_since_seconds:1548759560
slave_priority:100
slave_read_only:1
connected_slaves:0
master_replid:69255386899b5c3ddfe91e091c608ac448461620
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:4.59
used_cpu_user:9.78
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

Commandstats

cmdstat_auth:calls=10,usec=32,usec_per_call=3.20
cmdstat_info:calls=16,usec=736,usec_per_call=46.00

Cluster

cluster_enabled:0

Keyspace

db0:keys=25,expires=9,avg_ttl=0

------ CLIENT LIST OUTPUT ------
id=11 addr=127.0.0.1:44318 fd=9 name= age=0 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=ping
id=13 addr=172.30.158.37:48046 fd=11 name= age=0 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=ping

------ REGISTERS ------
9:S 29 Jan 10:59:39.263 #
RAX:0000000000000000 RBX:00007f82021ca2e0
RCX:0000000000000000 RDX:0000000000000000
RDI:0000000000000000 RSI:00007f82021ca2e0
RBP:00007f82353a0040 RSP:00007fffaad88c70
R8 :00007f82021ca280 R9 :6e69746961773a73
R10:00007f823522253b R11:0000000000000001
R12:0000000000000000 R13:00007fffaad88da0
R14:00007f82353a0040 R15:0000000000000000
RIP:0000558e3b741377 EFL:0000000000010202
CSGSFS:0000000000000033
9:S 29 Jan 10:59:39.263 # (00007fffaad88c7f) -> 0000558e3b76988a
9:S 29 Jan 10:59:39.263 # (00007fffaad88c7e) -> 00007f8204bd3af0
9:S 29 Jan 10:59:39.263 # (00007fffaad88c7d) -> 00007f82353a0040
9:S 29 Jan 10:59:39.263 # (00007fffaad88c7c) -> 00007f8204bd3ae8
9:S 29 Jan 10:59:39.263 # (00007fffaad88c7b) -> 0000558e3b741561
9:S 29 Jan 10:59:39.263 # (00007fffaad88c7a) -> 0000000000000001
9:S 29 Jan 10:59:39.263 # (00007fffaad88c79) -> 00007f82353a0040
9:S 29 Jan 10:59:39.263 # (00007fffaad88c78) -> 00007fffaad88da0
9:S 29 Jan 10:59:39.263 # (00007fffaad88c77) -> 0000000000000000
9:S 29 Jan 10:59:39.263 # (00007fffaad88c76) -> 00007f82353a0040
9:S 29 Jan 10:59:39.263 # (00007fffaad88c75) -> 0000000000000000
9:S 29 Jan 10:59:39.263 # (00007fffaad88c74) -> 00007f82021ca2e0
9:S 29 Jan 10:59:39.263 # (00007fffaad88c73) -> 00007f8235387000
9:S 29 Jan 10:59:39.263 # (00007fffaad88c72) -> 00007f82353a0040
9:S 29 Jan 10:59:39.263 # (00007fffaad88c71) -> 0000558e3b7418c5
9:S 29 Jan 10:59:39.263 # (00007fffaad88c70) -> 00007f8235387000

------ FAST MEMORY TEST ------
9:S 29 Jan 10:59:39.264 # Bio thread for job type #0 terminated
9:S 29 Jan 10:59:39.265 # Bio thread for job type #1 terminated
9:S 29 Jan 10:59:39.265 # Bio thread for job type #2 terminated
*** Preparing to test memory region 558e3ba70000 (98304 bytes)
*** Preparing to test memory region 558e3bcb5000 (1531904 bytes)
*** Preparing to test memory region 7f81fc800000 (922746880 bytes)
*** Preparing to test memory region 7f82339fe000 (8388608 bytes)
*** Preparing to test memory region 7f82341ff000 (8388608 bytes)
*** Preparing to test memory region 7f8234a00000 (12582912 bytes)
*** Preparing to test memory region 7f8235b21000 (16384 bytes)
*** Preparing to test memory region 7f8235d3e000 (16384 bytes)
*** Preparing to test memory region 7f8236465000 (8192 bytes)
*** Preparing to test memory region 7f823646a000 (12288 bytes)
*** Preparing to test memory region 7f823646f000 (4096 bytes)
.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: dictAddRaw (base: 0x558e3b741360)
Module: /usr/local/bin/redis-server 0.0.0.0:6379 (base 0x558e3b711000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x558e3b741360 -D -b binary -m i386:x86-64 /tmp/dump.bin

9:S 29 Jan 10:59:44.051 # dump of function (hexdump of 151 bytes):
415741564989ff415541544989d455534889f34883ec2848837f50ff740b48837f58000f8487010000498b074889dfff104d85e448890424740849c704240000000049837f50ff0f8493000000498d471048894424184989c5498d475048894424104c8b34244d2375104a8d04f5000000004889442408498b45004a8b2cf04885ed752ee9a70000000f1f8000000000498b07488b4018

=== REDIS BUG REPORT END. Make sure to include from START to END. ===

[soloestoy]

Hi @davissp14 , it's a known bug and fixed in PR #5248, but not been merged into 4.0 branch, you can try 5.0.2.

But I still wonder how it happens when loading aof, as I know even brpoplpush should not be blocked when loading data, could you send us your appendonly.aof?

[davissp14]

@soloestoy Unfortunately, we are working with a customer database, so we won't be able to share the .aof file.

[soloestoy]

OK @davissp14 , how about that you just grep the key in brpoplpush, and then send us the history about this key and replace it with another name?