Redisearch: Load crash when AOF enabled at encountering FT entries

[tw-bert]

We experienced a crash when loading from AOF at startup. The crash occurred after the Redis AOF loader hit some redisearch entries. After stripping the tail of the AOF, the load went without errors.

We have appendonly yes in the .conf. Also: aof-load-truncated yes , auto-aof-rewrite-percentage 0,
auto-aof-rewrite-min-size 0 (last two because we have our own daemon that does that).

Without RediSearch, the load from AOF goes fine. Without FT, we get something like DB loaded from append only file: 308.076 seconds in the log. The AOF file is around 4GB, ram usage around 7GB.

Error: aof.c:748 '(fakeClient->flags & CLIENT_BLOCKED) == 0' is not true (see crash report)

Offending AOF fragment (after our "normal" stuff, which involves a.o. a lot of EVALSHA calls):

*11
$9
FT.CREATE
$5
myIdx
$6
SCHEMA
$5
title
$4
TEXT
$6
WEIGHT
$3
5.0
$4
body
$4
TEXT
$3
url
$4
TEXT
*11
$6
FT.ADD
$5
myIdx
$4
doc1
$3
1.0
$6
FIELDS
$5
title
$11
hello world
$4
body
$11
lorem ipsum
$3
url
$15
http://redis.io
*4
$9
FT.SUGADD
$12
autocomplete
$11
hello world
$3
100
*4
$9
FT.SUGADD
$12
autocomplete
$11
hello world
$3
100
*2
$7
ft.drop
$5
myIdx
*2
$3
del
$12
autocomplete
*3
$3
set
$5
hello
$5
world
*11
$9
FT.CREATE
$5
myIdx
$6
SCHEMA
$5
title
$4
TEXT
$6
WEIGHT
$3
5.0
$4
body
$4
TEXT
$3
url
$4
TEXT
*11
$6
FT.ADD
$5
myIdx
$4
doc1
$3
1.0
$6
FIELDS
$5
title
$11
hello world
$4
body
$11
lorem ipsum
$3
url
$15
http://redis.io
*11
$6
FT.ADD
$5
myIdx
$4
doc1
$3
1.0
$6
FIELDS
$5
title
$11
hello world
$4
body
$11
lorem ipsum
$3
url
$15
http://redis.io
*11
$6
FT.ADD
$5
myIdx
$4
doc2
$3
1.0
$6
FIELDS
$5
title
$12
héllo world
$4
body
$11
lorem ipsum
$3
url
$15
http://redis.io
*11
$6
FT.ADD
$5
myIdx
$4
doc3
$3
1.0
$6
FIELDS
$5
title
$11
Hello world
$4
body
$11
lorem ipsum
$3
url
$15
http://redis.io
*2
$3
DEL
$5
hello
*3
$3
set
$6
-hello
$5
world
*3
$3
set
$6
.hello
$5
world
*3
$3
set
$6
+hello
$5
world
*3
$3
set
$6
|hello
$5
world
*3
$3
set
$6
&hello
$5
world

Crash report:

cat /var/log/redis_14213.log

1627:C 25 Oct 14:16:05.440 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1627:C 25 Oct 14:16:05.440 # Redis version=4.0.2, bits=64, commit=00000000, modified=0, pid=1627, just started
1627:C 25 Oct 14:16:05.440 # Configuration loaded
1628:M 25 Oct 14:16:05.442 * Increased maximum number of open files to 10032 (it was originally set to 1024).
1628:M 25 Oct 14:16:05.443 * Running mode=standalone, port=14213.
1628:M 25 Oct 14:16:05.443 # Server initialized
1628:M 25 Oct 14:16:05.443 * <ft> Configuration: concurrent mode: 1, ext load: (null)
1628:M 25 Oct 14:16:05.443 * <ft> Initialized thread pool!
1628:M 25 Oct 14:16:05.444 * Module 'ft' loaded from /usr/local/bin/RediSearch/0.21.4/redisearch.so


=== REDIS BUG REPORT START: Cut & paste starting from here ===
1628:M 25 Oct 14:21:18.297 # === ASSERTION FAILED ===
1628:M 25 Oct 14:21:18.297 # ==> aof.c:748 '(fakeClient->flags & CLIENT_BLOCKED) == 0' is not true
1628:M 25 Oct 14:21:18.297 # (forcing SIGSEGV to print the bug report.)
1628:M 25 Oct 14:21:18.297 # Redis 4.0.2 crashed by signal: 11
1628:M 25 Oct 14:21:18.297 # Crashed running the instuction at: 0x46aa9f
1628:M 25 Oct 14:21:18.297 # Accessing address: 0xffffffffffffffff
1628:M 25 Oct 14:21:18.297 # Failed assertion: (fakeClient->flags & CLIENT_BLOCKED) == 0 (aof.c:748)

------ STACK TRACE ------
EIP:
/usr/local/bin/redis-server *:14213(_serverAssert+0x6f)[0x46aa9f]

Backtrace:
/usr/local/bin/redis-server *:14213(logStackTrace+0x3c)[0x46afcc]
/usr/local/bin/redis-server *:14213(sigsegvHandler+0xa3)[0x46c223]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f91c78358d0]
/usr/local/bin/redis-server *:14213(_serverAssert+0x6f)[0x46aa9f]
/usr/local/bin/redis-server *:14213(loadAppendOnlyFile+0x63e)[0x4663ce]
/usr/local/bin/redis-server *:14213(loadDataFromDisk+0xac)[0x43031c]
/usr/local/bin/redis-server *:14213(main+0x46f)[0x43213f]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f91c749fb45]
/usr/local/bin/redis-server *:14213[0x4269c9]

------ INFO OUTPUT ------
# Server
redis_version:4.0.2
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:568e55027fe08492
redis_mode:standalone
os:Linux 2.6.32-5-amd64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:sync-builtin
gcc_version:4.4.7
process_id:1628
run_id:d2b8c3cb0911090e6d6cddf7973ed16a5fccc3e4
tcp_port:14213
uptime_in_seconds:0
uptime_in_days:0
hz:10
lru_clock:15761541
executable:/usr/local/bin/redis-server
config_file:/etc/redis/14213.conf

# Clients
connected_clients:0
client_longest_output_list:0
client_biggest_input_buf:0
blocked_clients:1

# Memory
used_memory:6862003048
used_memory_human:6.39G
used_memory_rss:0
used_memory_rss_human:0B
used_memory_peak:6862003048
used_memory_peak_human:6.39G
used_memory_peak_perc:100.07%
used_memory_overhead:763720
used_memory_startup:757616
used_memory_dataset:6861239328
used_memory_dataset_perc:100.00%
total_system_memory:33814462464
total_system_memory_human:31.49G
used_memory_lua:63488
used_memory_lua_human:62.00K
maxmemory:0
maxmemory_human:0B
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:35017884
rdb_bgsave_in_progress:0
rdb_last_save_time:1508933765
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:1508933765
loading_total_bytes:3977709581
loading_loaded_bytes:3973716966
loading_loaded_perc:99.90
loading_eta_seconds:0

# Stats
total_connections_received:5
total_commands_processed:5
instantaneous_ops_per_sec:0
total_net_input_bytes:70
total_net_output_bytes:14345
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
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:568d71342ea6f81c4ef2c2b76ee9dfea29214b16
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:1073741824
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

# CPU
used_cpu_sys:5.14
used_cpu_user:304.90
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

# Commandstats
cmdstat_info:calls=5,usec=328,usec_per_call=65.60

# Cluster
cluster_enabled:0

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

------ CLIENT LIST OUTPUT ------

------ REGISTERS ------
1628:M 25 Oct 14:21:18.298 #
RAX:0000000000000000 RBX:00000000000002ec
RCX:00007f91c7820678 RDX:0000000000000000
RDI:00007f91c7820620 RSI:0000000000000000
RBP:000000000050722b RSP:00007fff68429e30
R8 :00007f91c7820678 R9 :00007f91c7820670
R10:7562206568742074 R11:0000000000000206
R12:0000000000506648 R13:00007f901d5fa5b8
R14:00007f901d3d7d21 R15:00007fff68429f20
RIP:000000000046aa9f EFL:0000000000010206
CSGSFS:0000000000000033
1628:M 25 Oct 14:21:18.298 # (00007fff68429e3f) -> 00000000000081a4
1628:M 25 Oct 14:21:18.298 # (00007fff68429e3e) -> 0000000000000001
1628:M 25 Oct 14:21:18.298 # (00007fff68429e3d) -> 000000000000bad1
1628:M 25 Oct 14:21:18.298 # (00007fff68429e3c) -> 000000000000fe03
1628:M 25 Oct 14:21:18.298 # (00007fff68429e3b) -> 0000000168429f70
1628:M 25 Oct 14:21:18.298 # (00007fff68429e3a) -> 00007f901d5fa560
1628:M 25 Oct 14:21:18.298 # (00007fff68429e39) -> 00007f91c6c17010
1628:M 25 Oct 14:21:18.298 # (00007fff68429e38) -> 00000000ed170304
1628:M 25 Oct 14:21:18.298 # (00007fff68429e37) -> 0000000000085aa0
1628:M 25 Oct 14:21:18.298 # (00007fff68429e36) -> 00007f91c6d83a80
1628:M 25 Oct 14:21:18.298 # (00007fff68429e35) -> 00007fff68429f21
1628:M 25 Oct 14:21:18.298 # (00007fff68429e34) -> 0000000b68429e60
1628:M 25 Oct 14:21:18.298 # (00007fff68429e33) -> 00000000004663ce
1628:M 25 Oct 14:21:18.298 # (00007fff68429e32) -> 000000000000000b
1628:M 25 Oct 14:21:18.298 # (00007fff68429e31) -> 0000000002728be0
1628:M 25 Oct 14:21:18.298 # (00007fff68429e30) -> 0000000000000000

------ FAST MEMORY TEST ------
1628:M 25 Oct 14:21:18.299 # Bio thread for job type #0 terminated
1628:M 25 Oct 14:21:18.299 # Bio thread for job type #1 terminated
1628:M 25 Oct 14:21:18.299 # Bio thread for job type #2 terminated
*** Preparing to test memory region 740000 (94208 bytes)
*** Preparing to test memory region 271a000 (282624 bytes)
*** Preparing to test memory region 7f901bc00000 (2097152 bytes)
*** Preparing to test memory region 7f901bfff000 (8388608 bytes)
*** Preparing to test memory region 7f901c800000 (7038042112 bytes)
*** Preparing to test memory region 7f91c0152000 (8388608 bytes)
*** Preparing to test memory region 7f91c0953000 (8388608 bytes)
*** Preparing to test memory region 7f91c1154000 (8388608 bytes)
*** Preparing to test memory region 7f91c1955000 (8388608 bytes)
*** Preparing to test memory region 7f91c2156000 (8388608 bytes)
*** Preparing to test memory region 7f91c2957000 (8388608 bytes)
*** Preparing to test memory region 7f91c3158000 (8388608 bytes)
*** Preparing to test memory region 7f91c3959000 (8388608 bytes)
*** Preparing to test memory region 7f91c415a000 (8388608 bytes)
*** Preparing to test memory region 7f91c495b000 (8388608 bytes)
*** Preparing to test memory region 7f91c53fe000 (8388608 bytes)
*** Preparing to test memory region 7f91c5bff000 (8388608 bytes)
*** Preparing to test memory region 7f91c6400000 (10485760 bytes)
*** Preparing to test memory region 7f91c7200000 (2097152 bytes)
*** Preparing to test memory region 7f91c7822000 (16384 bytes)
*** Preparing to test memory region 7f91c7a3f000 (16384 bytes)
*** Preparing to test memory region 7f91c815a000 (16384 bytes)
*** Preparing to test memory region 7f91c8164000 (16384 bytes)
*** Preparing to test memory region 7f91c816a000 (4096 bytes)
.O.O.O.O.O.O.O.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: _serverAssert (base: 0x46aa30)
Module: /usr/local/bin/redis-server *:14213 (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x46aa30 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
1628:M 25 Oct 14:21:45.025 # dump of function (hexdump of 239 bytes):
48895c24e848896c24f089d34c896424f84883ec184989fc4889f5e8b0ffffffbeb2775000bf0300000031c0e81f54fcff4d89e089d94889eabecb775000bf0300000031c0e80654fcffbe207d5000bf0300000031c04c8925fb6d2d0048892dfc6d2d00891dfe6d2d00e8e153fcffc60425ffffffff78488b1c24488b6c24084c8b6424104883c418c3660f1f44000048895c24d048896c24d84889fb4c896424e04c896c24e84c897424f04c897c24f84881ec680800004883fe040f86ae0000004889f54883ed040f84a1000000488d7c2410b90001000031c04531e44c8d7b054c8db42410080000f348abeb09

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

[dvirsky]

OK, it looks like the concurrent indexing mechanism we've recently introduced doesn't play nicely with AOF. We'll have to detect AOF loading and treat it a bit differently. Thanks for reporting.

@antirez notice that I need to add a CTX_CLIENT_AOF to the context flags PR you merged a couple of weeks ago, for this to work....

PS it's also odd that our unit tests pass because we are testing loading from AOF. @mnunberg is checking how the hell our tests pass this assertion :)

[tw-bert]

Great you are looking into it. In the AOF fragment you can see I was testing collation, with an é in hello world (héllo world above, codepage conversion). Collation limitations are not an issue for us at all, I only mention it because of possible relevance to the issue.

Here is the binary version (gzipped), could be useful:

appendonly.aof.corrupt.tail.gz

[dvirsky]

It doesn't seem to be related. The report says that the check is outside of redis. But we're still investigating. Thanks a lot for reporting this.

[dvirsky]

@tw-bert can you send us your AOF file? We can't recreate it with just this snippet.

[tw-bert]

I'm afraid it is a 4GB file, and contains non public data. If you can't recreate it, I'll have to try to do it myself in a lighter scenario. That might take up to two weeks, my time is limited I'm afraid.

[dvirsky]

can you maybe snip the relevant part into a raw text file? I think github messes the line breaks when converting to markdown.

[mnunberg]

So i managed to reproduce the crash using your AOF pasted. I managed to hack the newlines using dos2unix :) redis-check-aof complained about trailing parts of the file, but at least the leading parts triggered it. I'll be investigating now.

[dvirsky]

great, no need to send us anything and hopefull we'll have a fix soon :)

[tw-bert]

great! BTW: you might have missed I attached a binary version of the snipped 30 mins ago, but that's not relevant anymore. dos2unix to the rescue ;)

[mnunberg]

So apparently AOF works with RediSearch if you let it rewrite the AOF file for you. When it rewrites the AOF file, it replaces commands such as ADD with dumps of its internal term trees. The original document itself of course just remains as a simple redis hash, and the tokens etc. are already in binary form under other keys.

This unfortunately doesn't help for a "raw" or pre-rewritten AOF file, as seems to be your case.

[tw-bert]

We did not do any manual manipulation of the AOF file. Redis made it. However, our redis configuration is as mentioned: AOF based, not RDB based. We are dependent on that configuration, since it is integrated with a rollforwarding and auditing system. At startup, redis automatically loads the AOF file. Before shutdown, redis wrote the AOF snippet pasted above, when we issued simple FT. commands in a redis-cli.

[dvirsky]

Ok, we've figured out what's going on, and we have a way to fix this - even without adding a way for the module to know if the client is actually a fake AOF client. The solution is to add another, AOF-safe command identical to FT.ADD, something like FT.SAFEADD or something similar. Then we can emit that command to the AOF instead of the original command - even before rewriting the AOF.

[tw-bert]

FT.SAFEADD being internal, and not an actual redis-cli command I presume?

[dvirsky]

there is no way to do that. Also, it would be useful as it could be used from Lua scripts and from MULTI transactions, whereas FT.ADD cannot be. It's a good addition to the API anyway!

[tw-bert]

Hmm, I'm not quite following the logic. Using RediSearch should be simple and straightforward. Two commands that essentially do the same thing sounds confusing.

If I reconfigure my server to appendonly no, apparently I don't want to have to change my client code ;)

[mnunberg]

@tw-bert the changes we're discussing here are mainly internal to what we need to do :) - You won't be forced to use a new command etc.

[dvirsky]

We have internal commands right now, we simply don't document them... but there's no way to make a command internal.

[tw-bert]

Perfectly clear.

One thing that might make the solution more simple: because this is happening at busyLoading time, there is no need to worry about concurrency. The only reason for multithreading would be load performance.

Thanks for all your speedy responses, very much looking forward to the fix. Let me know if there is anything I can do.

Cheers TW

[mnunberg]

@tw-bert try this branch. It should work. https://github.com/RedisLabsModules/RediSearch/tree/aof-fixes

I don't see any noticeable differences in performance before and after this fix (of course, AoF loading will be much slower, but I mean that the added checks don't indicate slowdown during normal paths)

[dvirsky]

Post rewriting the AOF it should still be super fast.

[tw-bert]

I can confirm this branch fixes the issue, great stuff.

Log (4GB AOF had FT entries at the end, no AOF rewrite was applied):

11381:C 25 Oct 23:07:24.457 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
11381:C 25 Oct 23:07:24.457 # Redis version=4.0.2, bits=64, commit=00000000, modified=0, pid=11381, just started
11381:C 25 Oct 23:07:24.457 # Configuration loaded
11382:M 25 Oct 23:07:24.461 * Increased maximum number of open files to 10032 (it was originally set to 1024).
11382:M 25 Oct 23:07:24.462 * Running mode=standalone, port=14213.
11382:M 25 Oct 23:07:24.462 # Server initialized
11382:M 25 Oct 23:07:24.463 * <ft> Configuration: concurrent mode: 1, ext load: (null)
11382:M 25 Oct 23:07:24.464 * <ft> Initialized thread pool!
11382:M 25 Oct 23:07:24.464 * Module 'ft' loaded from /usr/local/bin/RediSearch/0.21.4-aof-fixes/redisearch.so
11382:M 25 Oct 23:12:34.090 * DB loaded from append only file: 309.626 seconds
11382:M 25 Oct 23:12:34.090 * Ready to accept connections

and the AOF FT entries were succesfully indexed, at first glance:

127.0.0.1:14213> FT.SEARCH FTindex.AnythingGoes "hello world  " LIMIT 0 10
1) (integer) 2
2) "FT.doc.tryout_tw"
3) 1) "body"
   2) "Hello redisearch world"
4) "FT.doc.tryout_tw.2"
5) 1) "body"
   2) "Hello second redisearch world"

Performance was fine, no noticable delay (but will test with more FT data at a later stage - the tips on AOF rewrite are helpful indeed in our setup, since we might have to raise the frequency, which is now each 24h).

For the module list I might have expected 2104, considering the branch point, but that's just a remark:

127.0.0.1:14213> module list
1) 1) "name"
   2) "ft"
   3) "ver"
   4) (integer) 2103

Many thanks for the fix, and feel free to close this issue.

[mnunberg]

Yeah, it's missing versioning and some tests, but I'm glad to see it works for you. We'll bundle this fix up in our next (pre)release.