RediSearch can't load index from disk, corrupted RDB file

Created on 19 Jan 2018 · 19Comments · Source: RediSearch/RediSearch

It's the first time that this happens. Is there any known issue? I see nothing strange in the logs.
Is there anything I could try to fix the RDB file and recover the data?

91849:signal-handler (1516269514) Received SIGINT scheduling shutdown...
91849:M 18 Jan 10:58:34.636 # User requested shutdown...
91849:M 18 Jan 10:58:34.638 * Saving the final RDB snapshot before exiting.
91849:M 18 Jan 10:58:48.382 * <ft> Trie: saving 780501 nodes.
91849:M 18 Jan 10:58:57.429 * DB saved on disk
91849:M 18 Jan 10:58:57.429 * Removing the pid file.
91849:M 18 Jan 10:58:57.431 # Redis is now ready to exit, bye bye...

$ redis-server /usr/local/etc/redis-6380.conf
18330:M 19 Jan 17:55:55.305 # Server initialized
18330:M 19 Jan 17:55:55.307 * <ft> Configuration: concurrent mode: 0, ext load: (null), min prefix: 2, max expansions: 200,
18330:M 19 Jan 17:55:55.307 * <ft> Initialized thread pool!
18330:M 19 Jan 17:55:55.307 * Module 'ft' loaded from /usr/local/lib/redisearch-1.0.4.so
18330:M 19 Jan 17:55:57.674 # Error loading data from RDB (short read or EOF). Read performed by module 'ft' about type 'numericdx' after reading '0' bytes of a value.

Source

vruizext

All 19 comments

what version is this?

dvirsky on 19 Jan 2018

RediSearch 1.0.4, redis 4.0.6, on Mac OS 10.13.2

vruizext on 20 Jan 2018

Can you send me the RDB in question?

dvirsky on 20 Jan 2018

Yes I can upload it and send you a link. Where should I sent the link?

vruizext on 20 Jan 2018

dvir at redis labs dot com. Thanks!

dvirsky on 20 Jan 2018

The bad news is that the RDB is a goner. The good news is that I've found the bug and fixed it.

Basically, you created duplicate entires in the numeric index for the same document, and that corrupts the RDB.
I've located two ways you can do that:

This can happen if you add duplicate entires for the same numeric field in FT.ADD. i.e. FT.ADD idx doc1 1.0 FIELDS num 1 num 2 num 3
Performing partial update where the field name in the spec and/or the way you write it in the query differ. i.e.:

FT.CREATE idx SCHEMA TimeStamp NUMERIC
FT.ADD idx doc1 1.0 FIELDS timestamp 1
FT.ADD idx doc1 1.0 REPLACE PARTIAL FIELDS TiMeStaMp  2

(the latter will also create a document with the two fields as redis is case sensitive).

Fixed in master. Notice that I'm only protecting the index, we'll fix the issues on the indexer side in a different issue. You can still end up with a document that has the same field with two cases (following example 2), or with a document that has a different value than what's indexed, following example 1.

Thanks a lot for reporting this, it's a great bug.

dvirsky on 21 Jan 2018

I can confirm, in my case I was calling FT.ADD passing the same numeric field two times with different values

vruizext on 21 Jan 2018

I'm having the same issue as this in version with redis 4.0.9 and redisearch 1.0.9 running on OSX. I able to reproduce it reliably after running a set of unit tests.

^C80477:signal-handler (1522881144) Received SIGINT scheduling shutdown...
80477:M 04 Apr 18:32:24.137 # User requested shutdown...
80477:M 04 Apr 18:32:24.137 * Saving the final RDB snapshot before exiting.
80477:M 04 Apr 18:32:24.137 * <ft> Trie: saving 0 nodes.
80477:M 04 Apr 18:32:24.137 * <ft> Trie: saving 3 nodes.
80477:M 04 Apr 18:32:24.138 * <ft> Trie: saving 2 nodes.
80477:M 04 Apr 18:32:24.138 * <ft> Trie: saving 3 nodes.
80477:M 04 Apr 18:32:24.138 * <ft> Trie: saving 3 nodes.
80477:M 04 Apr 18:32:24.138 * <ft> Trie: saving 3 nodes.
80477:M 04 Apr 18:32:24.138 * <ft> Trie: saving 2 nodes.
80477:M 04 Apr 18:32:24.138 * <ft> Trie: saving 3 nodes.
80477:M 04 Apr 18:32:24.138 * <ft> Trie: saving 3 nodes.
80477:M 04 Apr 18:32:24.147 * DB saved on disk
80477:M 04 Apr 18:32:24.147 * Removing the pid file.
80477:M 04 Apr 18:32:24.147 # Redis is now ready to exit, bye bye...
 /u/l/etc  redis-server /usr/local/etc/redis.conf
80524:C 04 Apr 18:32:30.173 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
80524:C 04 Apr 18:32:30.173 # Redis version=4.0.9, bits=64, commit=00000000, modified=0, pid=80524, just started
80524:C 04 Apr 18:32:30.173 # Configuration loaded
80524:M 04 Apr 18:32:30.175 * Increased maximum number of open files to 10032 (it was originally set to 4864).
                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 4.0.9 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    '      ,       .-`  | `,    )     Running in standalone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6379
 |    `-._   `._    /     _.-'    |     PID: 80524
  `-._    `-._  `-./  _.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'

80524:M 04 Apr 18:32:30.176 # Server initialized
80524:M 04 Apr 18:32:30.180 * <ft> Configuration: concurrent mode: 1, ext load: (null), min prefix: 2, max expansions: 200, query timeout: 500ms
80524:M 04 Apr 18:32:30.180 * <ft> Initialized thread pool!
80524:M 04 Apr 18:32:30.180 * Module 'ft' loaded from /usr/local/etc/redisearch.so
80524:M 04 Apr 18:32:30.181 # Error loading data from RDB (short read or EOF). Read performed by module 'ft' about type 'ft_index0' after reading '0' bytes of a value.

JefStat on 5 Apr 2018

Any update on fixing the indexer? I'm going to work around the replace partial issue but would be nice to not have to tip toe around it.
This is my stacktrace after restarting redis. I achieve this by running

redis-cli FT.CREATE atest SCHEMA textfield TEXT numfield NUMERIC
redis-cli FT.ADD atest anId 1 PAYLOAD '{"hello":"world"}' FIELDS textfield sometext numfield 1234
redis-cli FT.ADD atest anId 1 PAYLOAD '{"hello":"world2"}' REPLACE PARTIAL FIELDS numfield 1111

=== REDIS BUG REPORT START: Cut & paste starting from here ===
14229:M 13 Jun 12:54:46.229 # Redis 4.0.9 crashed by signal: 11
14229:M 13 Jun 12:54:46.229 # Crashed running the instruction at: 0x7fff51c85f49
14229:M 13 Jun 12:54:46.229 # Accessing address: 0x7faea7800000
14229:M 13 Jun 12:54:46.229 # Failed assertion: <no assertion failed> (<no file>:0)

------ STACK TRACE ------
EIP:
0   libsystem_platform.dylib            0x00007fff51c85f49 _platform_memmove$VARIANT$Haswell + 41

Backtrace:
0   redis-server                        0x0000000102a544ce logStackTrace + 110
1   redis-server                        0x0000000102a5485b sigsegvHandler + 236
2   libsystem_platform.dylib            0x00007fff51c82f5a _sigtramp + 26
3   ???                                 0x0000000000000000 0x0 + 0
4   redisearch.so                       0x0000000102bc0b5f LoadByteOffsets + 223
5   redisearch.so                       0x0000000102bc5062 DocTable_RdbLoad + 786
6   redisearch.so                       0x0000000102be5c99 IndexSpec_RdbLoad + 585
7   redis-server                        0x0000000102a3748e rdbLoadObject + 2435
8   redis-server                        0x0000000102a37e32 rdbLoadRio + 1358
9   redis-server                        0x0000000102a38026 rdbLoad + 70
10  redis-server                        0x0000000102a1d76a loadDataFromDisk + 292
11  redis-server                        0x0000000102a1e0be main + 1224
12  libdyld.dylib                       0x00007fff51974015 start + 1
13  ???                                 0x0000000000000002 0x0 + 2

------ INFO OUTPUT ------
# Server
redis_version:4.0.9
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:e0c8d37381c486c6
redis_mode:standalone
os:Darwin 17.5.0 x86_64
arch_bits:64
multiplexing_api:kqueue
atomicvar_api:atomic-builtin
gcc_version:4.2.1
process_id:14229
run_id:91daf5d2ab32246773b0f17c339fa612128485f9
tcp_port:6379
uptime_in_seconds:0
uptime_in_days:0
hz:10
lru_clock:2182230
executable:/Users/jefstatham/projects/connect-installers/redis-server
config_file:/usr/local/etc/redis.conf

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

# Memory
used_memory:1672927792
used_memory_human:1.56G
used_memory_rss:0
used_memory_rss_human:0B
used_memory_peak:1672927792
used_memory_peak_human:1.56G
used_memory_peak_perc:inf%
used_memory_overhead:1055488
used_memory_startup:980864
used_memory_dataset:1671872304
used_memory_dataset_perc:100.00%
total_system_memory:8589934592
total_system_memory_human:8.00G
used_memory_lua:37888
used_memory_lua_human:37.00K
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
mem_fragmentation_ratio:0.00
mem_allocator:libc
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:1528908886
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:1528908886
loading_total_bytes:343203
loading_loaded_bytes:0
loading_loaded_perc:0.00
loading_eta_seconds:1

# Stats
total_connections_received:0
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
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

# Replication
role:master
connected_slaves:0
master_replid:fb758971cb9b97ee1afdf2d7deccdd5127e5699f
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:0.04
used_cpu_user:0.03
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

# Commandstats

# Cluster
cluster_enabled:0

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

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

------ REGISTERS ------
14229:M 13 Jun 12:54:46.241 #
RAX:0000000111336000 RBX:00007faea5630df0
RCX:000000006188bc0d RDX:0000000063a5ae7f
RDI:0000000113505272 RSI:00007faea7800000
RBP:00007ffeed1ee110 RSP:00007ffeed1ee110
R8 :0000000102b60798 R9 :00000000000000a9
R10:0000000102b60000 R11:ffff80526bd05272
R12:00007faea5630e10 R13:000000000000036a
R14:0000000000000000 R15:0000000063a5ae7f
RIP:00007fff51c85f49 EFL:0000000000010202
CS :000000000000002b FS:0000000000000000  GS:0000000000000000
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee11f) -> 00007ffeed1ee260
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee11e) -> 0000000000000004
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee11d) -> 0000000000000001
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee11c) -> 0000000000000005
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee11b) -> 0000000000000004
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee11a) -> 00000000ffffffff
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee119) -> 0000000102bc5062
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee118) -> 00007ffeed1ee1c0
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee117) -> 0000000000000000
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee116) -> 0000000000000001
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee115) -> 00007faea5630a20
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee114) -> 00007faea5630ce0
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee113) -> 00007faea5630df0
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee112) -> 00007faea5630df0
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee111) -> 0000000102bc0b5f
14229:M 13 Jun 12:54:46.241 # (00007ffeed1ee110) -> 00007ffeed1ee150

------ DUMPING CODE AROUND EIP ------
Symbol: _platform_memmove$VARIANT$Haswell (base: 0x7fff51c85f20)
Module: /usr/lib/system/libsystem_platform.dylib (base 0x7fff51c81000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x7fff51c85f20 -D -b binary -m i386:x86-64 /tmp/dump.bin
------
14229:M 13 Jun 12:54:46.241 # dump of function (hexdump of 169 bytes):
554889e54989fb4929f34889f84939d3721b4883fa60762f4881fa004000000f82cb0000004889d1fcf3a45dc34839fe74f94801d64801d74883fa600f828c010000e9a90100004883fa107656c5f8104c16f04883ea20762ac5fc1006c5fc11074883c6204883c7204883ea207214c5fc1006c5fc11074883c6204883c7204883ea204883c2107e0cc5f81006c5f81107c5f857c0c5f8110c17c5f057c95dc5f877c34883ea087210

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

JefStat on 13 Jun 2018

@JefStat what version of RS are you using (still 1.0.9?) This appears to be fixed, though admittedly I haven't looked into this yet. Can you write me a python script which can reproduce this issue, or step-by-step reproduction?

mnunberg on 13 Jun 2018

python script no sorry. I can spot you some bash. I'm using redisearch 1.2.0 with redis 4.0.9

#!/bin/bash
redis-server /usr/local/etc/redis.conf daemonize yes
sleep 1
redis-cli FT.CREATE atest SCHEMA textfield TEXT numfield NUMERIC
redis-cli FT.ADD atest anId 1 PAYLOAD '{"hello":"world"}' FIELDS textfield sometext numfield 1234
redis-cli FT.ADD atest anId 1 PAYLOAD '{"hello":"world2"}' REPLACE PARTIAL FIELDS numfield 1111

redis-cli shutdown
redis-server /usr/local/etc/redis.conf

# cleanup
# rm /usr/local/var/db/redis/dump.rdb

Also the stacktrace from earlier today that's the first time I have seen that stack trace. Normally I don't notice failures until after redis restarts.

JefStat on 13 Jun 2018

I've just tried this with current master, and there is no problem here. We did some things to the numeric index.

mnunberg on 13 Jun 2018

The issue still exists on master with a new error. To reproduce I wait before shutting down.
New startup error
23810:M 13 Jun 15:35:17.052 # Error loading data from RDB (short read or EOF). Read performed by module 'ft' about type 'numericdx' after reading '0' bytes of a value.

Added a 10s sleep before shutting down redis

#!/bin/bash
redis-server /usr/local/etc/redis.conf daemonize yes
sleep 1
redis-cli FT.CREATE atest SCHEMA textfield TEXT numfield NUMERIC
redis-cli FT.ADD atest anId 1 PAYLOAD '{"hello":"world"}' FIELDS textfield sometext numfield 1234
redis-cli FT.ADD atest anId 1 PAYLOAD '{"hello":"world2"}' REPLACE PARTIAL FIELDS numfield 1111
sleep 10
redis-cli shutdown
redis-server /usr/local/etc/redis.conf

# cleanup
#rm /usr/local/var/db/redis/dump.rdb

JefStat on 13 Jun 2018

Investigated it, the payload leads to rdb damage.

When updateing a document containing any payload, the rdb is unreadable.

Work well:
FT.CREATE atest SCHEMA textfield TEXT numfield NUMERIC
FT.ADD atest anId 1 FIELDS textfield sometext numfield 1234
FT.ADD atest anId 1 REPLACE PARTIAL FIELDS numfield 1111

Same behavior when updating using addhash replace

salt4pommes on 13 Jun 2018

👍1

Thanks @salt4pommes. Removing payloads works with 1.2.0 but fails on master.

#!/bin/bash
redis-server /usr/local/etc/redis.conf daemonize yes
sleep 1
redis-cli FT.CREATE atest SCHEMA numfield NUMERIC
redis-cli FT.ADD atest anId 1 FIELDS numfield 1234
redis-cli FT.ADD atest anId 1 REPLACE PARTIAL FIELDS numfield 1111
sleep 10
redis-cli shutdown
redis-server /usr/local/etc/redis.conf

JefStat on 13 Jun 2018

👍1

I am encountering the same problem with redisearch 1.2.0 redis 4.0.10.

I can't tell which command caused the corruption, but I can reproduce it from a clean installation using the steps by @JefStat above.

127.0.0.1:6379> module list
1) 1) "name"
   2) "ft"
   3) "ver"
   4) (integer) 10200
127.0.0.1:6379> redis-cli FT.CREATE atest SCHEMA textfield TEXT numfield NUMERIC
(error) ERR unknown command 'redis-cli'
127.0.0.1:6379> FT.CREATE atest SCHEMA textfield TEXT numfield NUMERIC
OK
127.0.0.1:6379> FT.ADD atest anId 1 PAYLOAD '{"hello":"world"}' FIELDS textfield sometext numfield 1234
OK
127.0.0.1:6379> FT.ADD atest anId 1 PAYLOAD '{"hello":"world2"}' REPLACE PARTIAL FIELDS numfield 1111
OK
127.0.0.1:6379> SHUTDOWN

redis-server /home/redis/redis-4.0.10/redis.conf &
.....
12614:M 20 Jun 12:37:04.052 * Module 'ft' loaded from /home/redis/redis-4.0.10/redisearch.so
12614:M 20 Jun 12:37:04.052 # Error loading data from RDB (short read or EOF). Read performed by module 'ft' about type 'numericdx' after reading '0' bytes of a value.

mmasouras on 20 Jun 2018

I recommend re-opening this issue until it's resolved. Our production db is now in a state where
backups are corrupt, which means it's irrecoverable if it goes down!

This also means that copying the latest backup for local development doesn't work either.

mmasouras on 20 Jun 2018

@mmasouras @JefStat Can you open a new issue with the script, etc. - I'm not entirely sure it's related to the original.

mnunberg on 20 Jun 2018

We're seeing a similar issue with this, about type ft_index0.

1:M 17 Apr 2019 15:22:17.393 * <ft> RediSearch version 1.4.6 (Git=)
1:M 17 Apr 2019 15:22:17.393 * <ft> concurrency: ON, gc: ON, prefix min length: 2, prefix max expansions: 200, query timeout (ms): 500, timeout policy: return, cursor read size: 1000, cursor max idle (ms): 300000, max doctable size: 1000000, search pool size: 20, index pool size: 8,
1:M 17 Apr 2019 15:22:17.394 * <ft> Initialized thread pool!
1:M 17 Apr 2019 15:22:17.394 * Module 'ft' loaded from /usr/lib/redis/modules/redisearch.so
1:M 17 Apr 2019 15:22:17.394 * Reading RDB preamble from AOF file...
1:M 17 Apr 2019 15:22:17.410 # Error loading data from RDB (short read or EOF). Read performed by module 'ft' about type 'ft_index0' after reading '0' bytes of a value.