RediSearch crash with BGSAVE

[tw-bert]

RediSearch 1.0.5 , Redis 4.0.7
(also happens on RediSearch 1.0.4, Redis 4.0.6, but upgraded and repro'd to avoid any fuzz over a fixed issue)

After issuing a BGSAVE:

25396:C 24 Jan 14:43:34.387 # Redis 4.0.7 crashed by signal: 11
25396:C 24 Jan 14:43:34.387 # Crashed running the instruction at: 0x7f3eea498085
25396:C 24 Jan 14:43:34.387 # Accessing address: (nil)
25396:C 24 Jan 14:43:34.387 # Failed assertion: <no assertion failed> (<no file>:0)

------ STACK TRACE ------
EIP:
/usr/local/bin/RediSearch/1.0.5/redisearch.so(SortingVector_RdbSave+0x15)[0x7f3eea498085]

Backtrace:
redis-rdb-bgsave *:14213(logStackTrace+0x3c)[0x46b81c]
redis-rdb-bgsave *:14213(sigsegvHandler+0xa3)[0x46ca73]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f3eecd6f8d0]
/usr/local/bin/RediSearch/1.0.5/redisearch.so(SortingVector_RdbSave+0x15)[0x7f3eea498085]
/usr/local/bin/RediSearch/1.0.5/redisearch.so(DocTable_RdbSave+0x1ec)[0x7f3eea48d3ac]
/usr/local/bin/RediSearch/1.0.5/redisearch.so(IndexSpec_RdbSave+0x9b)[0x7f3eea481e1b]
redis-rdb-bgsave *:14213(rdbSaveObject+0x408)[0x44d0e8]
redis-rdb-bgsave *:14213(rdbSaveKeyValuePair+0x9c)[0x44d2ec]
redis-rdb-bgsave *:14213(rdbSaveRio+0x2b6)[0x44d5b6]
redis-rdb-bgsave *:14213(rdbSave+0x95)[0x44d785]
redis-rdb-bgsave *:14213(rdbSaveBackground+0xa0)[0x44da50]
redis-rdb-bgsave *:14213(bgsaveCommand+0xdf)[0x44dc9f]
redis-rdb-bgsave *:14213(call+0x87)[0x42dc97]
redis-rdb-bgsave *:14213(processCommand+0x36d)[0x42e30d]
redis-rdb-bgsave *:14213(processInputBuffer+0x10d)[0x43e5bd]
redis-rdb-bgsave *:14213(aeProcessEvents+0x15d)[0x42945d]
redis-rdb-bgsave *:14213(aeMain+0x2b)[0x42977b]
redis-rdb-bgsave *:14213(main+0x512)[0x4323d2]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f3eec9d9b45]
--snip--
------ CURRENT CLIENT INFO ------
id=142179 addr=127.0.0.1:51334 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=bgsave
argv[0]: 'bgsave'
6428:M 24 Jan 14:43:34.553 # Background saving terminated by signal 11

The BGSAVE failed, but the instance keeps running.
I can do a BGREWRITEAOF, and use it to restore to another redis instance.
A BGSAVE on that redis instance crashes as well.

Sidenote: AOF is around 5GB and NDA.

[dvirsky]

Do you delete documents from the db? It might be an issue with a deleted document. Let me see where the crash exactly is.

If possible could you load the AOF on a different instance and run redis in gdb, so we can get a proper stack trace?

[tw-bert]

Our documents are only used in one FT index per doc.
We do delete them, if we delete the index entry. Here's Lua:

redis.call('FT.DEL','some_ftidx', 'some_ftdoc@' .. some_hash)
redis.call('DEL','some_ftdoc@' .. some_hash) -- Also delete the document. See: https://github.com/RedisLabsModules/RediSearch/issues/78#issuecomment-309682458

I'd like to set up gdb, but can't do that right now (our redis development VM needs upgrading, old debian distro... apt repo no longer maintained).

[dvirsky]

IIRC FT.DEL only accepts one key per call

Can you share your schema? or at least: how many fields do you have? how many of them are sortable?

[tw-bert]

Sure, I anonymized it a bit, but this is all:

FT.CREATE "~ftidx.lo.aaa" STOPWORDS 0 SCHEMA iIDLiAaa NUMERIC SORTABLE iIDLiAaa__tag TAG SEPARATOR ";" cAaa TEXT NOINDEX SORTABLE dtAaa NUMERIC SORTABLE dtBbb NUMERIC SORTABLE dtmEee NUMERIC SORTABLE iQtyGgg NUMERIC NOINDEX iQtyBGg NUMERIC NOINDEX fKpp NUMERIC fFff NUMERIC iIDLiKS TAG SEPARATOR ";" cLll TAG SEPARATOR ";" bVvv TAG SEPARATOR ";" multisort__Xxx NUMERIC NOINDEX SORTABLE
FT.CREATE "~ftidx.lo.bbb" STOPWORDS 0 SCHEMA amama NUMERIC SORTABLE didid TAG SEPARATOR ";" lelele TAG SEPARATOR ";" ununun TAG SEPARATOR ";" unssss TAG SEPARATOR ";" multisort__xxx TEXT NOINDEX SORTABLE
FT.CREATE "~ftidx.lo.ccc" STOPWORDS 0 SCHEMA iIDLiYyy NUMERIC SORTABLE cYyy TEXT NOINDEX SORTABLE cSvCcc TEXT NOSTEM iMmm TAG SEPARATOR ";" cSvRyy TEXT NOSTEM cKeyIiii TAG SEPARATOR ";"

[dvirsky]

We can protect against what happens easily but we're trying to understand why it happens.
If you reload from AOF and save it happens immediately?

[tw-bert]

To be more precise: First command (well, I did INFO) after reload from AOF (which went 100% ok) was a BGSAVE -> crash, after a couple of seconds. Within those seconds, a partial RDB has been created. That RDB was (unsurprisingly) incomplete (tested a load -> premature EOF detected).

[dvirsky]

what happens is that the sorting table of one of the document is NULL. Again, checking for this is easy but it also means a bug.

Are you doing PARTIAL REPLACE updates? REPLACE updates?

[tw-bert]

All writes to FT are done with 'FT.SAFEADD' and 'REPLACE'. No partial.

[tw-bert]

The following is probably completely unrelated:

For a totally different non-redisearch usecase, redis.set_repl(redis.REPL_AOF) and redis.set_repl(redis.REPL_ALL) are used, including switching to "Lua effects replication" by redis.replicate_commands() at beginning of script.

In this script are also FT commands, outside of the REPL_AOF/REPL_ALL block.
But the complete script is now executed as "effects replication" instead of "script replication".

I have no idea if we already had this BGSAVE bug before switching that script to "effects replication".

[tw-bert]

Just now, I tried to give you the tail of the partial rdb (you never know, could shed some light on the issue).
Alas, the partial rdb is automatically deleted at the crash:

-rw-r--r-- 1 root root 4485364603 Jan 24 16:25 appendonly.aof
-rw-r--r-- 1 root root  582377472 Jan 24 16:41 temp-11623.rdb
root@srv-flux-dev-01:/var/lib/redis/14213# ls -ltr
total 5007520
-rw-r--r-- 1 root root 4485364603 Jan 24 16:25 appendonly.aof
-rw-r--r-- 1 root root  637313024 Jan 24 16:41 temp-11623.rdb
root@srv-flux-dev-01:/var/lib/redis/14213# ls -ltr
total 5059252
-rw-r--r-- 1 root root 4485364603 Jan 24 16:25 appendonly.aof
-rw-r--r-- 1 root root  690229248 Jan 24 16:41 temp-11623.rdb
root@srv-flux-dev-01:/var/lib/redis/14213# ls -ltr
total 4384532
-rw-r--r-- 1 root root 4485364603 Jan 24 16:25 appendonly.aof

[mnunberg]

We were able to reproduce this - apparently we don't save the SV in AOF, but we do send the flags. This fix should be simple, so hang on.

[tw-bert]

That's awesome, thanks for your reply. So far this hasn't caused a live issue over here yet btw (only some developer hassle).

[dvirsky]

@tw-bert this means that with the current version, you will lose the sortable values when loading from AOF after a rewrite of it (which happens periodically). So it's more than the crash.

Mark is writing a fix for both now.

[dvirsky]

steps to reporduce it BTW:

127.0.0.1:6379> ft.create idx schema foo text sortable bar numeric sortable
OK
127.0.0.1:6379> ft.add idx 1 1 fields foo text bar 1234
OK
127.0.0.1:6379> BGREWRITEAOF
Background append only file rewriting started
127.0.0.1:6379> debug loadaof
OK
127.0.0.1:6379> save
Could not connect to Redis at 127.0.0.1:6379: Connection refused

[dvirsky]

@tw-bert another important note - if you have production machines with both AOF and RDB, you will not lose data until you restart them and load from AOF. So when upgrading after we fix this:

1. dump to RDB with BGSAVE.
2. then remove the rewritten AOF
3. then upgrades so that the new redis instance takes the data from RDB and not AOF.

Then you can safely return to AOF with no data loss.

[tw-bert]

@dvirsky Great info, thanks for the heads up. So it seems our per-second AOF rollforward archive is compromised... ah well, the price of early adapting, no regrets ;)

[mnunberg]

@tw-bert https://github.com/RedisLabsModules/RediSearch/tree/aof-sv-save fresh off the press. see if this fixes your issue!

[tw-bert]

@mnunberg Great. Off tm, will test on Friday

[dvirsky]

@tw-bert not so fast, nothing is lost yet! as long as you haven't restarted since the AOF rewrite you are fine. What happens is that AOF rewrite skips the sorting keys, which will cause this, but only after you load from AOF. If you have a server that's been up and never loaded from AOF - it's fine. Just persist to RDB or spin up a backup slave and you'll be good.

Also, AOF rewrite per second is crazy for 5G, it probably takes a minute to complete the rewrite. I guess and hope you mean AOF fsync every second, which is a great setting. AOF rewrite refers to the compaction process, that can be done even every 24 hours without risk as long as you have enough disk space.

[tw-bert]

@dvirsky You misunderstand my words (my words were unclear). We only fsync each sec, not a complete bgrewriteaof. We have a daemon process that polls each 0.5 sec for filesize changes of the AOF file, records the offsets, and sends a slice of what happened (in that second) to another (live, LAN) server, where it's archived. The daemon does one bgrewriteaof per day (configurable), and all auto-aof-rewrites inside redis are turned off.

We have another service (on a dev server) that enables us to roll forward a developer redis instance to any point in time of the live redis instance. We use that daily to update a development system, in sync with a nightly live RDBMS backup restore. It is also a huge help to track down live issues at a certain point in time.

It's that archive that is compromised. A bit of a shame, but no huge issue for us.

[dvirsky]

You can always replicate that from the actual servers. RDB persistence is fine, so you can sync the fixed version from a master (slave full sync uses rdb, not aof), then do BGREWRITEAOF, then you have a perfect AOF.

[tw-bert]

@dvirsky I think you miss the point of the archive. If I want the exact data of 11h11m this morning, I can't use a fresh AOF.

[dvirsky]

I understand, just saying you won't need to rebuild the data from scratch.

On Wed, Jan 24, 2018, 11:59 PM tw-bert [e-mail] wrote:

@dvirsky https://github.com/dvirsky I think you miss the point of the
archive. If I want the exact data of 11h11m this morning, I can't use a
fresh AOF.

—
You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub
https://github.com/RedisLabsModules/RediSearch/issues/277#issuecomment-360287875,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAetum8-ZKckN82P8mviWxiQLu8DoGvFks5tN6e8gaJpZM4RrSlO
.

[tw-bert]

@mnunberg @dvirsky The patch seems to work fine.

Tested with:

1. Reloaded a dev instance with (fresh) live dump.rdb
2. dev bgrewriteaof
3. Reloaded dev instance from aof
4. Issued a BGSAVE -> no crash anymore
5. Issued an FT.SEARCH with sorting -> seems to work fine

Is it possible to do a 1.0.6 bugfix release? We prefer to use releases-only in our live environment (for backreferencing).

[dvirsky]

@tw-bert we'll release 1.0.6 tomorrow.

[dvirsky]

Well, better late than never. 1.0.6 just released. It also negates the need to use SAFEADD from Lua. Enjoy, this one is 100% for you :)

[tw-bert]

Excellent news! A version addressed solely to me _-sniff, in awe-_ I'll take good care of it ;)

[tw-bert]

@dvirsky @mnunberg FYI: We just upgraded to Redis 4.0.7 + RediSearch 1.0.6, and all fixes are working fine. We have replaced FT.SAFEADD with FT.ADD in all Lua scripts, and removed SAFEMODE from all redis conf files. We were able to do the contingency switcheroo RDB<->AOF as recommended by @dvirsky , which indeed prevented manual re-population of the indexes. Great work guys!

[dvirsky]

@tw-bert great to hear!

BTW we're going to release the aggregation engine next week if all goes well. Will you have any use for it? If so we'd appreciate you playing with it a bit.

[tw-bert]

@dvirsky In spite of its awesomeness, we have no immediate usecases for aggregations. Maybe for time series data, but we already use disk-based storage for that (InfluxDB). We'll definitely think about it.

I'll probably focus on RediSearch performance profiling in the near future, I'll keep you posted.

[tw-bert]

@dvirsky Is it possible that the fix is not completely merged into 1.0.6?

We're still seeing issues : sort not working on AOF restored copy. Crashes are gone though.
I thought I tested this properly, but now I'm unsure.

[tw-bert]

@dvirsky @mnunberg : The bug is definitely still there. Since the crash itself is fixed, I opened a new issue: https://github.com/RedisLabsModules/RediSearch/issues/282

[dvirsky]

Thanks. @mnunberg please investigate...

On Mon, Feb 5, 2018 at 10:00 AM tw-bert [e-mail] wrote:

@dvirsky https://github.com/dvirsky @mnunberg
https://github.com/mnunberg : The bug is definitely still there. Since
the crash itself is fixed, I opened a new issue: #282
https://github.com/RedisLabsModules/RediSearch/issues/282

—
You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub
https://github.com/RedisLabsModules/RediSearch/issues/277#issuecomment-363007764,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAetuhVwC08E4NwhsXU67MAlubw5_BEeks5tRrUqgaJpZM4RrSlO
.